turnip

Merge lp:~wgrant/turnip/pack-logging into lp:turnip

  1. pack-logging
  2. Merge into turnip
Proposed by William Grant
Status: Merged
Merged at revision: 191
Proposed branch: lp:~wgrant/turnip/pack-logging
Merge into: lp:turnip
Diff against target: 171 lines (+50/-1)
3 files modified
turnip/pack/git.py (+43/-0)
turnip/pack/http.py (+5/-1)
turnip/pack/ssh.py (+2/-0)
To merge this branch: bzr merge lp:~wgrant/turnip/pack-logging
Reviewer Review Type Date Requested Status
Colin Watson (community) Approve
Review via email: mp+277545@code.launchpad.net

Commit message

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

Description of the change

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.

To post a comment you must log in.
lp:~wgrant/turnip/pack-logging updated
191. By William Grant

Derp.

Revision history for this message
Colin Watson (cjwatson) wrote :

Yay!

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'turnip/pack/git.py'
2--- turnip/pack/git.py 2015-06-02 12:52:50 +0000
3+++ turnip/pack/git.py 2015-11-16 10:07:23 +0000
4@@ -12,10 +12,12 @@
5
6 from twisted.internet import (
7 defer,
8+ error,
9 protocol,
10 reactor,
11 )
12 from twisted.internet.interfaces import IHalfCloseableProtocol
13+from twisted.logger import Logger
14 # twisted.web.xmlrpc doesn't exist for Python 3 yet, but the non-XML-RPC
15 # bits of this module work.
16 if sys.version_info.major < 3: # noqa
17@@ -40,6 +42,15 @@
18 SAFE_PARAMS = frozenset(['host'])
19
20
21+class RequestIDLogger(Logger):
22+
23+ def emit(self, level, format=None, **kwargs):
24+ request_id = getattr(self.source, 'request_id')
25+ if format is not None and request_id is not None:
26+ format = '[request-id=%s] %s' % (request_id, format)
27+ super(RequestIDLogger, self).emit(level, format=format, **kwargs)
28+
29+
30 class UnstoppableProducerWrapper(object):
31 """An `IPushProducer` that won't be stopped.
32
33@@ -149,6 +160,15 @@
34 got_request = False
35 peer = None
36
37+ request_id = None
38+ log = RequestIDLogger()
39+
40+ def extractRequestMeta(self, command, pathname, params):
41+ self.request_id = params.get(b'turnip-request-id', None)
42+ self.log.info(
43+ "Request received: '{command} {pathname}', params={params}",
44+ command=command, pathname=pathname, params=params)
45+
46 def requestReceived(self, command, pathname, params):
47 """Begin handling of a git pack protocol request.
48
49@@ -180,7 +200,15 @@
50 def rawDataReceived(self, data):
51 self.peer.sendRawData(data)
52
53+ def connectionLost(self, reason):
54+ if reason.check(error.ConnectionDone):
55+ self.log.info('Connection closed.')
56+ else:
57+ self.log.failure('Connection closed.', failure=reason)
58+ PackProxyProtocol.connectionLost(self, reason)
59+
60 def die(self, message):
61+ self.log.info('Dying: {message}', message=message)
62 self.sendPacket(ERROR_PREFIX + message + b'\n')
63 self.transport.loseConnection()
64
65@@ -291,6 +319,9 @@
66 self.command = command
67 self.pathname = pathname
68 self.params = params
69+ self.log.info(
70+ "Connecting to backend: {command} {pathname}, params={params}",
71+ command=command, pathname=pathname, params=params)
72 client = self.client_factory(self)
73 reactor.connectTCP(
74 self.factory.backend_host, self.factory.backend_port, client)
75@@ -315,6 +346,8 @@
76 hookrpc_key = None
77
78 def requestReceived(self, command, raw_pathname, params):
79+ self.extractRequestMeta(command, raw_pathname, params)
80+
81 path = compose_path(self.factory.root, raw_pathname)
82 if command == b'git-upload-pack':
83 subcmd = b'upload-pack'
84@@ -344,6 +377,7 @@
85 env[b'TURNIP_HOOK_RPC_SOCK'] = self.factory.hookrpc_sock
86 env[b'TURNIP_HOOK_RPC_KEY'] = self.hookrpc_key
87
88+ self.log.info('Spawning {args}', args=args)
89 self.peer = GitProcessProtocol(self)
90 reactor.spawnProcess(self.peer, cmd, args, env=env)
91
92@@ -380,16 +414,20 @@
93
94 @defer.inlineCallbacks
95 def requestReceived(self, command, pathname, params):
96+ self.extractRequestMeta(command, pathname, params)
97 permission = b'read' if command == b'git-upload-pack' else b'write'
98 proxy = xmlrpc.Proxy(self.factory.virtinfo_endpoint, allowNone=True)
99 try:
100 can_authenticate = (
101 params.get(b'turnip-can-authenticate') == b'yes')
102 auth_uid = params.get(b'turnip-authenticated-uid')
103+ self.log.info("Translating request.")
104 translated = yield proxy.callRemote(
105 b'translatePath', pathname, permission,
106 int(auth_uid) if auth_uid is not None else None,
107 can_authenticate)
108+ self.log.info(
109+ "Translation result: {translated}", translated=translated)
110 if 'trailing' in translated and translated['trailing']:
111 self.die(
112 VIRT_ERROR_PREFIX +
113@@ -450,9 +488,14 @@
114 client_factory = PackFrontendClientFactory
115
116 def requestReceived(self, command, pathname, params):
117+ self.request_id = str(uuid.uuid4())
118+ self.log.info(
119+ "Request received: '{command} {pathname}', params={params}",
120+ command=command, pathname=pathname, params=params)
121 if set(params.keys()) - SAFE_PARAMS:
122 self.die(b'Illegal request parameters')
123 return
124+ params[b'turnip-request-id'] = self.request_id
125 self.connectToBackend(command, pathname, params)
126
127
128
129=== modified file 'turnip/pack/http.py'
130--- turnip/pack/http.py 2015-11-12 11:43:11 +0000
131+++ turnip/pack/http.py 2015-11-16 10:07:23 +0000
132@@ -17,6 +17,7 @@
133 except ImportError:
134 from urllib import urlencode
135 import sys
136+import uuid
137 import zlib
138
139 from openid.consumer import consumer
140@@ -258,7 +259,10 @@
141 The turnip-authenticated-user parameter is set to the username
142 returned by the virt service, if any.
143 """
144- params = {b'turnip-can-authenticate': b'yes'}
145+ params = {
146+ b'turnip-can-authenticate': b'yes',
147+ b'turnip-request-id': str(uuid.uuid4()),
148+ }
149 authenticated_user, authenticated_uid = yield self.authenticateUser(
150 request)
151 if authenticated_user:
152
153=== modified file 'turnip/pack/ssh.py'
154--- turnip/pack/ssh.py 2015-07-09 12:23:31 +0000
155+++ turnip/pack/ssh.py 2015-11-16 10:07:23 +0000
156@@ -8,6 +8,7 @@
157 )
158
159 import shlex
160+import uuid
161
162 from lazr.sshserver.auth import (
163 LaunchpadAvatar,
164@@ -151,6 +152,7 @@
165 params = {
166 b'turnip-authenticated-user': self.avatar.username.encode('utf-8'),
167 b'turnip-authenticated-uid': str(self.avatar.user_id),
168+ b'turnip-request-id': str(uuid.uuid4()),
169 }
170 d = defer.Deferred()
171 client_factory = factory(service, path, params, ssh_protocol, d)

Subscribers

People subscribed via source and target branches

to all changes: