wireproto logging: capture getpack

Summary:
ignore-conflict-markers

This updates Mercurial to add a loggetpack option for wire proto logging that
allows capturing getpack responses. This will be useful to verify correctness
for ovrsource on Mononoke (right now, Mononoke isn't serving traffic for hosts
that use getpack).

Reviewed By: StanislavGlebik

Differential Revision: D17091537

fbshipit-source-id: 755a429949d7645010dddab95202c613025f2984

edenscm/hgext/remotefilelog/remotefilelogserver.py

@@ -342,7 +342,7 @@ def getfiles(repo, proto):
         fin = proto.fin
         args = []
         responselen = 0
-        start_time = time.time()
+        starttime = time.time()
 
         while True:
             request = fin.readline()[:-1]
@@ -370,28 +370,7 @@ def getfiles(repo, proto):
             proto.fout.flush()
 
         if repo.ui.configbool("wireproto", "loggetfiles"):
-            try:
-                serializedargs = json.dumps(args)
-            except Exception:
-                serializedargs = "Failed to serialize arguments"
-
-            kwargs = {}
-            try:
-                clienttelemetry = extensions.find("clienttelemetry")
-                kwargs = clienttelemetry.getclienttelemetry(repo)
-            except KeyError:
-                pass
-            reponame = repo.ui.config("common", "reponame", "unknown")
-            kwargs["reponame"] = reponame
-            repo.ui.log(
-                "wireproto_requests",
-                "",
-                command="getfiles",
-                args=serializedargs,
-                responselen=responselen,
-                duration=int((time.time() - start_time) * 1000),
-                **kwargs
-            )
+            _logwireprotorequest(repo, "getfiles", starttime, responselen, args)
 
     return wireproto.streamres(streamer())
 
@@ -535,8 +514,13 @@ def getpack(repo, proto, args, version=1):
         """
         files = _receivepackrequest(proto.fin)
 
+        args = []
+        responselen = 0
+        starttime = time.time()
+
         # Sort the files by name, so we provide deterministic results
         for filename, nodes in sorted(files.iteritems()):
+            args.append([filename, [hex(n) for n in nodes]])
             fl = repo.file(filename)
 
             # Compute history
@@ -561,11 +545,23 @@ def getpack(repo, proto, args, version=1):
             for chunk in wirepack.sendpackpart(
                 filename, history, chain, version=version
             ):
+                responselen += len(chunk)
                 yield chunk
 
-        yield wirepack.closepart()
+        close = wirepack.closepart()
+        responselen += len(close)
+        yield close
         proto.fout.flush()
 
+        if repo.ui.configbool("wireproto", "loggetpack"):
+            _logwireprotorequest(
+                repo,
+                "getpackv1" if version == 1 else "getpackv2",
+                starttime,
+                responselen,
+                args,
+            )
+
     return wireproto.streamres(streamer())
 
 
@@ -616,3 +612,30 @@ def _getdeltachain(fl, nodes, version):
 
     chain.reverse()
     return chain
+
+
+def _logwireprotorequest(repo, name, starttime, responselen, args):
+    try:
+        serializedargs = json.dumps(args)
+    except Exception:
+        serializedargs = "Failed to serialize arguments"
+
+    kwargs = {}
+    try:
+        clienttelemetry = extensions.find("clienttelemetry")
+        kwargs = clienttelemetry.getclienttelemetry(repo)
+    except KeyError:
+        pass
+
+    reponame = repo.ui.config("common", "reponame", "unknown")
+    kwargs["reponame"] = reponame
+
+    repo.ui.log(
+        "wireproto_requests",
+        "",
+        command=name,
+        args=serializedargs,
+        responselen=responselen,
+        duration=int((time.time() - starttime) * 1000),
+        **kwargs
+    )

edenscm/mercurial/helptext.py

@@ -2902,11 +2902,16 @@ Examples::
     Whether to log wireproto getfiles requests or not. "sampling.py" extension
     can be used to send list of log entries to log aggregator.
 
+``loggetpack``
+    Whether to log wireproto getpack requests or not. "sampling.py" extension
+    can be used to send list of log entries to log aggregator.
+
 Examples::
 
     [wireproto]
     logrequests = getbundle,gettreepack
     loggetfiles = True
+    loggetpack = True
 
     [sampling]
     key.wireproto_requests=perfpipe_wireprotorequests

tests/helpers-wireprotologging.sh

@@ -0,0 +1,36 @@
+capturewireprotologs() {
+  cat >> "$TESTTMP/uilog.py" <<EOF
+from edenscm.mercurial import extensions
+from edenscm.mercurial import ui as uimod
+
+def uisetup(ui):
+    extensions.wrapfunction(uimod.ui, 'log', mylog)
+
+def mylog(orig, self, service, *msg, **opts):
+    if service in ['wireproto_requests']:
+        kw = []
+        for k, v in sorted(opts.iteritems()):
+          if k == 'args':
+            v = eval(v)
+            for arg in v:
+              if isinstance(arg, dict):
+                v = sorted(list(arg.iteritems()))
+            v = str(v)
+          kw.append("%s=%s" % (k, v))
+        kwstr = ", ".join(kw)
+        msgstr = msg[0] % msg[1:]
+        self.warn('%s: %s (%s)\n' % (service, msgstr, kwstr))
+        with open('$TESTTMP/loggedrequests', 'a') as f:
+          f.write('%s: %s (%s)\n' % (service, msgstr, kwstr))
+    return orig(self, service, *msg, **opts)
+EOF
+
+  cat >> "$HGRCPATH" <<EOF
+[extensions]
+uilog=$TESTTMP/uilog.py
+
+[wireproto]
+logrequests=batch,branchmap,getbundle,hello,listkeys,lookup,between,unbundle
+loggetpack=True
+EOF
+}

tests/test-log-wireproto-requests-getpack.t

@@ -0,0 +1,58 @@
+  $ . "$TESTDIR/library.sh"
+  $ . "$TESTDIR/helpers-wireprotologging.sh"
+
+Create repo, enable capture requests
+  $ newserver master
+  $ capturewireprotologs
+
+Clone repo, make changes
+  $ clone master client1
+  $ cd client1
+  $ echo x > x
+  $ hg commit -qAm x
+  $ mkdir dir
+  $ echo y > dir/y
+  $ hg commit -qAm y
+  $ hg push -r tip --to master --create -q
+  remote: adding changesets (?)
+  remote: adding manifests (?)
+  remote: adding file changes (?)
+  remote: added 2 changesets with 2 changes to 2 files (?)
+  $ cd ..
+
+Make getpackv1 request
+  $ clone master v1 --noupdate
+  $ cd v1
+  $ cat >> .hg/hgrc <<EOF
+  > [remotefilelog]
+  > fetchpacks=True
+  > getpackversion=1
+  > EOF
+
+  $ clearcache
+
+  $ hg up -q tip
+  fetching tree '' 05bd2758dd7a25912490d0633b8975bf52bfab06, found via 79c51fb96423
+  2 trees fetched over *s (glob)
+  2 files fetched over 1 fetches - (2 misses, 0.00% hit ratio) over *s (glob)
+
+Make getpackv2 request
+  $ clone master v2 --noupdate
+  $ cd v2
+  $ cat >> .hg/hgrc <<EOF
+  > [remotefilelog]
+  > fetchpacks=True
+  > getpackversion=2
+  > EOF
+
+  $ clearcache
+
+  $ hg up -q tip
+  fetching tree '' 05bd2758dd7a25912490d0633b8975bf52bfab06, found via 79c51fb96423
+  2 trees fetched over *s (glob)
+  2 files fetched over 1 fetches - (2 misses, 0.00% hit ratio) over *s (glob)
+
+Check logged requests
+  $ grep 'getpack' $TESTTMP/loggedrequests
+  wireproto_requests:  (args=[['dir/y', ['076f5e2225b3ff0400b98c92aa6cdf403ee24cca']], ['x', ['1406e74118627694268417491f018a4a883152f0']]], command=getpackv1, duration=*, reponame=unknown, responselen=*) (glob)
+  wireproto_requests:  (args=[['dir/y', ['076f5e2225b3ff0400b98c92aa6cdf403ee24cca']], ['x', ['1406e74118627694268417491f018a4a883152f0']]], command=getpackv2, duration=*, reponame=unknown, responselen=*) (glob)

tests/test-log-wireproto-requests.t

@@ -1,32 +1,9 @@
+  $ . "$TESTDIR/helpers-wireprotologging.sh"
   $ setconfig extensions.treemanifest=!
   $ CACHEDIR=`pwd`/hgcache
-  $ cat >> $TESTTMP/uilog.py <<EOF
-  > from edenscm.mercurial import extensions
-  > from edenscm.mercurial import ui as uimod
-  > def uisetup(ui):
-  >     extensions.wrapfunction(uimod.ui, 'log', mylog)
-  > def mylog(orig, self, service, *msg, **opts):
-  >     if service in ['wireproto_requests']:
-  >         kw = []
-  >         for k, v in sorted(opts.iteritems()):
-  >           if k =='args':
-  >             v = eval(v)
-  >             for arg in v:
-  >               if isinstance(arg, dict):
-  >                 v = sorted(list(arg.iteritems()))
-  >             v = str(v)
-  >           kw.append("%s=%s" % (k, v))
-  >         kwstr = ", ".join(kw)
-  >         msgstr = msg[0] % msg[1:]
-  >         self.warn('%s: %s (%s)\n' % (service, msgstr, kwstr))
-  >         with open('$TESTTMP/loggedrequests', 'a') as f:
-  >           f.write('%s: %s (%s)\n' % (service, msgstr, kwstr))
-  >     return orig(self, service, *msg, **opts)
-  > EOF
 
   $ cat >> $HGRCPATH <<EOF
   > [extensions]
-  > uilog=$TESTTMP/uilog.py
   > remotefilelog=
   > [ui]
   > ssh = python "$TESTDIR/dummyssh"
@@ -35,6 +12,7 @@
   > EOF
 
   $ hg init repo
+  $ capturewireprotologs
   $ cd repo
   $ cat >> .hg/hgrc <<EOF
   > [remotefilelog]