launchpad-reviewers team mailing list archive

[William Grant <me@xxxxxxxxxxxxxxxxxx>]

William Grant has proposed merging lp:~wgrant/turnip/pack-logging into lp:turnip.

Commit message:
Give each pack frontend request an ID, and log it through the stack.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)

For more details, see:
https://code.launchpad.net/~wgrant/turnip/pack-logging/+merge/277545

Give each pack frontend request an ID, and log it through the stack. It's now vaguely possible to see what the services are doing, though there are a few iterations to go.
-- 
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~wgrant/turnip/pack-logging into lp:turnip.

=== modified file 'turnip/pack/git.py'
--- turnip/pack/git.py	2015-06-02 12:52:50 +0000
+++ turnip/pack/git.py	2015-11-16 10:04:20 +0000
@@ -12,12 +12,14 @@
 
 from twisted.internet import (
     defer,
+    error,
     protocol,
     reactor,
     )
 from twisted.internet.interfaces import IHalfCloseableProtocol
 # twisted.web.xmlrpc doesn't exist for Python 3 yet, but the non-XML-RPC
 # bits of this module work.
+from twisted.logger import Logger
 if sys.version_info.major < 3:  # noqa
     from twisted.web import xmlrpc
 from zope.interface import implementer
@@ -40,6 +42,15 @@
 SAFE_PARAMS = frozenset(['host'])
 
 
+class RequestIDLogger(Logger):
+
+    def emit(self, level, format=None, **kwargs):
+        request_id = getattr(self.source, 'request_id')
+        if format is not None and request_id is not None:
+            format = '[request-id=%s] %s' % (request_id, format)
+        super(RequestIDLogger, self).emit(level, format=format, **kwargs)
+
+
 class UnstoppableProducerWrapper(object):
     """An `IPushProducer` that won't be stopped.
 
@@ -149,6 +160,15 @@
     got_request = False
     peer = None
 
+    request_id = None
+    log = RequestIDLogger()
+
+    def extractRequestMeta(self, command, pathname, params):
+        self.request_id = params.get(b'turnip-request-id', None)
+        self.log.info(
+            "Request received: '{command} {pathname}', params={params}",
+            command=command, pathname=pathname, params=params)
+
     def requestReceived(self, command, pathname, params):
         """Begin handling of a git pack protocol request.
 
@@ -180,7 +200,15 @@
     def rawDataReceived(self, data):
         self.peer.sendRawData(data)
 
+    def connectionLost(self, reason):
+        if reason.check(error.ConnectionDone):
+            self.log.info('Connection closed.')
+        else:
+            self.log.failure('Connection closed.', failure=reason)
+        PackProxyProtocol.connectionLost(self, reason)
+
     def die(self, message):
+        self.log.info('Dying: {message}', message=message)
         self.sendPacket(ERROR_PREFIX + message + b'\n')
         self.transport.loseConnection()
 
@@ -291,6 +319,9 @@
         self.command = command
         self.pathname = pathname
         self.params = params
+        self.log.info(
+            "Connecting to backend: {command} {pathname}, params={params}",
+            command=command, pathname=pathname, params=params)
         client = self.client_factory(self)
         reactor.connectTCP(
             self.factory.backend_host, self.factory.backend_port, client)
@@ -315,6 +346,8 @@
     hookrpc_key = None
 
     def requestReceived(self, command, raw_pathname, params):
+        self.extractRequestMeta(command, raw_pathname, params)
+
         path = compose_path(self.factory.root, raw_pathname)
         if command == b'git-upload-pack':
             subcmd = b'upload-pack'
@@ -344,6 +377,7 @@
             env[b'TURNIP_HOOK_RPC_SOCK'] = self.factory.hookrpc_sock
             env[b'TURNIP_HOOK_RPC_KEY'] = self.hookrpc_key
 
+        self.log.info('Spawning {args}', args=args)
         self.peer = GitProcessProtocol(self)
         reactor.spawnProcess(self.peer, cmd, args, env=env)
 
@@ -380,16 +414,20 @@
 
     @defer.inlineCallbacks
     def requestReceived(self, command, pathname, params):
+        self.extractRequestMeta(command, pathname, params)
         permission = b'read' if command == b'git-upload-pack' else b'write'
         proxy = xmlrpc.Proxy(self.factory.virtinfo_endpoint, allowNone=True)
         try:
             can_authenticate = (
                 params.get(b'turnip-can-authenticate') == b'yes')
             auth_uid = params.get(b'turnip-authenticated-uid')
+            self.log.info("Translating request.")
             translated = yield proxy.callRemote(
                 b'translatePath', pathname, permission,
                 int(auth_uid) if auth_uid is not None else None,
                 can_authenticate)
+            self.log.info(
+                "Translation result: {translated}", translated=translated)
             if 'trailing' in translated and translated['trailing']:
                 self.die(
                     VIRT_ERROR_PREFIX +
@@ -450,9 +488,14 @@
     client_factory = PackFrontendClientFactory
 
     def requestReceived(self, command, pathname, params):
+        self.request_id = str(uuid.uuid4())
+        self.log.info(
+            "Request received: '{command} {pathname}', params={params}",
+            command=command, pathname=pathname, params=params)
         if set(params.keys()) - SAFE_PARAMS:
             self.die(b'Illegal request parameters')
             return
+        params[b'turnip-request-id'] = self.request_id
         self.connectToBackend(command, pathname, params)
 
 

=== modified file 'turnip/pack/http.py'
--- turnip/pack/http.py	2015-11-12 11:43:11 +0000
+++ turnip/pack/http.py	2015-11-16 10:04:20 +0000
@@ -17,6 +17,7 @@
 except ImportError:
     from urllib import urlencode
 import sys
+import uuid
 import zlib
 
 from openid.consumer import consumer
@@ -258,7 +259,10 @@
         The turnip-authenticated-user parameter is set to the username
         returned by the virt service, if any.
         """
-        params = {b'turnip-can-authenticate': b'yes'}
+        params = {
+            b'turnip-can-authenticate': b'yes',
+            b'turnip-request-id': str(uuid.uuid4()),
+            }
         authenticated_user, authenticated_uid = yield self.authenticateUser(
             request)
         if authenticated_user:

=== modified file 'turnip/pack/ssh.py'
--- turnip/pack/ssh.py	2015-07-09 12:23:31 +0000
+++ turnip/pack/ssh.py	2015-11-16 10:04:20 +0000
@@ -8,6 +8,7 @@
     )
 
 import shlex
+import uuid
 
 from lazr.sshserver.auth import (
     LaunchpadAvatar,
@@ -151,6 +152,7 @@
         params = {
             b'turnip-authenticated-user': self.avatar.username.encode('utf-8'),
             b'turnip-authenticated-uid': str(self.avatar.user_id),
+            b'turnip-request-id': str(uuid.uuid4()),
             }
         d = defer.Deferred()
         client_factory = factory(service, path, params, ssh_protocol, d)