Merge lp:~mwhudson/launchpad/puller-more-useful-xmlrpc-logs into lp:launchpad

Proposed by Michael Hudson-Doyle
Status: Merged
Approved by: Michael Hudson-Doyle
Approved revision: no longer in the source branch.
Merged at revision: not available
Proposed branch: lp:~mwhudson/launchpad/puller-more-useful-xmlrpc-logs
Merge into: lp:launchpad
Diff against target: 100 lines
3 files modified
Makefile (+0/-2)
cronscripts/supermirror-pull.py (+3/-3)
lib/canonical/twistedsupport/loggingsupport.py (+41/-0)
To merge this branch: bzr merge lp:~mwhudson/launchpad/puller-more-useful-xmlrpc-logs
Reviewer Review Type Date Requested Status
Tim Penhey (community) Approve
Review via email: mp+12562@code.launchpad.net

Commit message

Make the logging the puller does about XML-RPC requests more useful.

To post a comment you must log in.
Revision history for this message
Michael Hudson-Doyle (mwhudson) wrote :

Hi,

This branch removes useless crap from the puller logs and puts in some hopefully useful crap instead. The puller logs now look like this:

2009-09-29 01:11:58 INFO Log opened.
2009-09-29 01:11:58 INFO Sending request [0]: acquireBranchToPull()
2009-09-29 01:11:58 INFO Reply to request [0]: []
2009-09-29 01:11:58 INFO Mirroring complete
2009-09-29 01:11:58 INFO Sending request [1]: recordSuccess('branch-puller', 'grond', (2009, 9, 29, 1, 11, 58, 1, 272, 0), (2009, 9, 29, 1, 11, 58, 1, 272, 0))
2009-09-29 01:11:58 INFO Reply to request [1]: True
2009-09-29 01:11:58 INFO Main loop terminated.
mwh@grond:puller-more-useful-xmlrpc-logs$ /home/mwh/canonical/checkouts/puller-more-useful-xmlrpc-logs/bin/py cronscripts/supermirror-pull.py
2009-09-29 01:12:12 INFO Log opened.
2009-09-29 01:12:12 INFO Sending request [0]: acquireBranchToPull()
2009-09-29 01:12:12 INFO Reply to request [0]: [79, 'lp-hosted:///~mark/applets/wibbles', '~mark/applets/wibbles', '', 'HOSTED']
2009-09-29 01:12:12 INFO Sending request [1]: acquireBranchToPull()
2009-09-29 01:12:12 INFO Reply to request [1]: []
2009-09-29 01:12:15 INFO Mirroring branch 79: lp-hosted:///~mark/applets/wibbles to lp-mirrored:///~mark/applets/wibbles
2009-09-29 01:12:15 INFO Sending request [2]: startMirroring(79,)
2009-09-29 01:12:15 INFO Reply to request [2]: True
2009-09-29 01:12:15 INFO Sending request [3]: setStackedOn(79, '')
2009-09-29 01:12:15 INFO Reply to request [3]: True
2009-09-29 01:12:15 INFO Successfully mirrored branch 79 lp-hosted:///~mark/applets/wibbles to lp-mirrored:///~mark/applets/wibbles to rev <email address hidden>
2009-09-29 01:12:15 INFO Sending request [4]: mirrorComplete(79, '<email address hidden>')
2009-09-29 01:12:15 INFO Reply to request [4]: True
2009-09-29 01:12:15 INFO Mirroring complete
2009-09-29 01:12:15 INFO Sending request [5]: recordSuccess('branch-puller', 'grond', (2009, 9, 29, 1, 12, 12, 1, 272, 0), (2009, 9, 29, 1, 12, 15, 1, 272, 0))
2009-09-29 01:12:15 INFO Reply to request [5]: True
2009-09-29 01:12:15 INFO Main loop terminated.

Cheers,
mwh

Revision history for this message
Tim Penhey (thumper) wrote :

More is better than less, especially when we have no idea what is wrong :-|

Thanks for this.

review: Approve
Revision history for this message
Jonathan Lange (jml) wrote :

Michael, I think that the logged XML-RPC calls should be DEBUG level, rather than INFO level. Tim says we should demote them later.

Other than that, massive improvement. Thanks,
jml

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'Makefile'
2--- Makefile 2009-09-28 11:12:51 +0000
3+++ Makefile 2009-10-01 22:48:14 +0000
4@@ -197,8 +197,6 @@
5 bin/killservice librarian
6
7 pull_branches: support_files
8- # Mirror the hosted branches in the development upload area to the
9- # mirrored area.
10 $(PY) cronscripts/supermirror-pull.py
11
12 scan_branches:
13
14=== modified file 'cronscripts/supermirror-pull.py'
15--- cronscripts/supermirror-pull.py 2009-07-23 02:07:29 +0000
16+++ cronscripts/supermirror-pull.py 2009-10-01 22:48:14 +0000
17@@ -10,12 +10,12 @@
18
19 from twisted.internet import defer, reactor
20 from twisted.python import log as tplog
21-from twisted.web.xmlrpc import Proxy
22
23 from lp.codehosting.puller import mirror, scheduler
24 from canonical.config import config
25 from canonical.launchpad.scripts import logger_options
26-from canonical.twistedsupport.loggingsupport import set_up_logging_for_script
27+from canonical.twistedsupport.loggingsupport import (
28+ LoggingProxy, set_up_logging_for_script)
29
30 def clean_shutdown(ignored):
31 reactor.stop()
32@@ -43,7 +43,7 @@
33 parser.error("Unhandled arguments %s" % repr(arguments))
34 log = set_up_logging_for_script(options, 'supermirror_puller')
35 manager = scheduler.JobScheduler(
36- Proxy(config.codehosting.branch_puller_endpoint), log)
37+ LoggingProxy(config.codehosting.branch_puller_endpoint, log), log)
38
39 reactor.callWhenRunning(run_mirror, log, manager)
40 reactor.run()
41
42=== modified file 'lib/canonical/twistedsupport/loggingsupport.py'
43--- lib/canonical/twistedsupport/loggingsupport.py 2009-06-25 05:30:52 +0000
44+++ lib/canonical/twistedsupport/loggingsupport.py 2009-10-01 22:48:14 +0000
45@@ -17,10 +17,12 @@
46
47 import bz2
48 import glob
49+import logging
50 import os
51
52 from twisted.python import log
53 from twisted.python.logfile import DailyLogFile
54+from twisted.web import xmlrpc
55
56 from canonical.launchpad.scripts import logger
57 from canonical.launchpad.webapp import errorlog
58@@ -147,3 +149,42 @@
59 """Return the list of rotate log files, newest first."""
60 return sorted(glob.glob("%s.*" % self.path), reverse=True)
61
62+
63+class _QuietQueryFactory(xmlrpc._QueryFactory):
64+ """Override noisy to false to avoid useless log spam."""
65+ noisy = False
66+
67+
68+class LoggingProxy(xmlrpc.Proxy):
69+ """A proxy that logs requests and the corresponding responses."""
70+
71+ queryFactory = _QuietQueryFactory
72+
73+ def __init__(self, url, logger, level=logging.INFO):
74+ """Contstruct a `LoggingProxy`.
75+
76+ :param url: The URL to which to post method calls.
77+ :param logger: The logger to log requests and responses to.
78+ :param level: The log level at which to log requests and responses.
79+ """
80+ xmlrpc.Proxy.__init__(self, url)
81+ self.logger = logger
82+ self.level = level
83+ self.request_count = 0
84+
85+ def callRemote(self, method, *args):
86+ """See `xmlrpc.Proxy.callRemote`.
87+
88+ In addition to the superclass' behavior, we log the call and its
89+ result.
90+ """
91+ request = self.request_count
92+ self.request_count += 1
93+ self.logger.log(
94+ self.level, 'Sending request [%d]: %s%s', request, method, args)
95+ def _logResult(result):
96+ self.logger.log(
97+ self.level, 'Reply to request [%d]: %s', request, result)
98+ return result
99+ deferred = xmlrpc.Proxy.callRemote(self, method, *args)
100+ return deferred.addBoth(_logResult)