pkgme

Merge lp:~jml/pkgme/debug-logging into lp:pkgme

  1. debug-logging
  2. Merge into trunk
Proposed by Jonathan Lange
Status: Merged
Approved by: James Westby
Approved revision: 83
Merged at revision: 71
Proposed branch: lp:~jml/pkgme/debug-logging
Merge into: lp:pkgme
Diff against target: 256 lines (+79/-9)
8 files modified
.testr.conf (+1/-1)
pkgme/backend.py (+7/-0)
pkgme/bin/main.py (+9/-1)
pkgme/project_info.py (+10/-3)
pkgme/run_script.py (+4/-1)
pkgme/tests/test_trace.py (+26/-0)
pkgme/trace.py (+11/-2)
pkgme/write.py (+11/-1)
To merge this branch: bzr merge lp:~jml/pkgme/debug-logging
Reviewer Review Type Date Requested Status
James Westby Approve
Review via email: mp+69812@code.launchpad.net

Description of the change

This branch adds a debug flag and quite a few more debug logging statements.

Partly addresses bug 809440 and 809431.

Fixes a bug in the logging where it would truncate the log on each run.

There's no way to turn debugging off, but there's no use case for that yet.

To post a comment you must log in.
Revision history for this message
Jonathan Lange (jml) wrote :
Download full text (4.3 KiB)

Example log output::

2011-07-29 15:54:51,607 - DEBUG - Building packaging for /home/jml/src/pkgme/examples/brukkon-2.1.5.9.orig
2011-07-29 15:54:51,736 - DEBUG - Loading backends from: /home/jml/src/pkgme/debug-logging/pkgme/backends
2011-07-29 15:54:51,736 - DEBUG - Found backend python
2011-07-29 15:54:51,736 - DEBUG - Found backend binary
2011-07-29 15:54:51,736 - DEBUG - Found backend vala
2011-07-29 15:54:51,736 - DEBUG - Found backend cmake
2011-07-29 15:54:51,736 - DEBUG - Loading backends from: /usr/share/pkgme/backends
2011-07-29 15:54:51,736 - DEBUG - Finding backend for /home/jml/src/pkgme/examples/brukkon-2.1.5.9.orig
2011-07-29 15:54:51,736 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/python/want...
2011-07-29 15:54:51,761 - DEBUG - python scored 0
2011-07-29 15:54:51,762 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/want...
2011-07-29 15:54:51,999 - DEBUG - binary scored 10
2011-07-29 15:54:51,999 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/vala/want...
2011-07-29 15:54:52,003 - DEBUG - vala scored 0
2011-07-29 15:54:52,004 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/cmake/want...
2011-07-29 15:54:52,030 - DEBUG - cmake scored 0
2011-07-29 15:54:52,030 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/extra_files...
2011-07-29 15:54:52,274 - DEBUG - extra_files returned '{"debian/brukkon.desktop": "[Desktop Entry]\\nType=Application\\nVersion=1.0\\nExec=/opt/brukkon/src/Brukkon\\nCategories=\\nName=Brukkon\\nComment=\\n", "debian/install": "argparse opt/brukkon\\nos opt/brukkon\\nsrc opt/brukkon\\nsys opt/brukkon\\ndebian/brukkon.desktop usr/share/application\\n"}'
2011-07-29 15:54:52,275 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/depends...
2011-07-29 15:54:52,510 - DEBUG - depends returned '${shlibs:Depends}, ${misc:Depends}'
2011-07-29 15:54:52,510 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/architecture...
2011-07-29 15:54:52,514 - DEBUG - architecture returned None
2011-07-29 15:54:52,515 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/debhelper_addons...
2011-07-29 15:54:52,522 - DEBUG - debhelper_addons returned None
2011-07-29 15:54:52,523 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/description...
2011-07-29 15:54:52,528 - DEBUG - description returned None
2011-07-29 15:54:52,528 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/build_depends...
2011-07-29 15:55:29,113 - DEBUG - build_depends returned 'ia32-libs, lib32stdc++6, lib32gcc1, lib32asound2, libc6-i386'
2011-07-29 15:55:29,114 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/homepage...
2011-07-29 15:55:29,118 - DEBUG - homepage returned None
2011-07-29 15:55:29,119 - DEBUG - Running script /home/jml/src/pkgme/debug-logging/pkgme/backends/binary/version...
2011-07-29 15:55:29,122 - DEBUG - version returned None
2011-07-29 15:55:29,123 - DEBUG - Running script /home/jml/src/pkgme/debug-lo...

Read more...

Revision history for this message
James Westby (james-w) :
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
=== modified file '.testr.conf'
--- .testr.conf 2010-11-03 00:32:55 +0000
+++ .testr.conf 2011-07-29 14:58:42 +0000
@@ -1,3 +1,3 @@
1[DEFAULT]1[DEFAULT]
2test_command=python -m subunit.run $IDLIST2test_command=PYTHONPATH=`pwd` python -m subunit.run $IDLIST
3test_id_list_default=pkgme.tests.test_suite3test_id_list_default=pkgme.tests.test_suite
44
=== modified file 'pkgme/backend.py'
--- pkgme/backend.py 2011-07-12 16:34:59 +0000
+++ pkgme/backend.py 2011-07-29 14:58:42 +0000
@@ -11,6 +11,7 @@
11 SingleExternalHelperInfo,11 SingleExternalHelperInfo,
12 )12 )
13from pkgme.run_script import run_script, ScriptMissing13from pkgme.run_script import run_script, ScriptMissing
14from pkgme import trace
1415
1516
16def get_backend_dir(underunder_file, backend):17def get_backend_dir(underunder_file, backend):
@@ -173,8 +174,10 @@
173 def get_info(self, path):174 def get_info(self, path):
174 high_score = 0175 high_score = 0
175 eligble = []176 eligble = []
177 trace.debug('Finding backend for %s' % (path,))
176 for backend in self.backends:178 for backend in self.backends:
177 score = backend.want(path)179 score = backend.want(path)
180 trace.debug(' %s scored %s' % (backend.name, score))
178 if score > high_score:181 if score > high_score:
179 eligble = [backend]182 eligble = [backend]
180 high_score = score183 high_score = score
@@ -187,6 +190,8 @@
187 if len(eligble) > 1:190 if len(eligble) > 1:
188 eligble.sort(key=attrgetter('name'))191 eligble.sort(key=attrgetter('name'))
189 backend = eligble[0]192 backend = eligble[0]
193 trace.debug(
194 '%s eligble backends. Picked %s' % (len(eligble), backend.name))
190 return backend.get_info(path)195 return backend.get_info(path)
191196
192197
@@ -205,6 +210,7 @@
205 backends = []210 backends = []
206 names = set()211 names = set()
207 for path in self.paths:212 for path in self.paths:
213 trace.debug("Loading backends from: %s" % (path,))
208 path = os.path.abspath(path)214 path = os.path.abspath(path)
209 if not os.path.isdir(path):215 if not os.path.isdir(path):
210 continue216 continue
@@ -217,6 +223,7 @@
217 backend_path = os.path.join(path, fname)223 backend_path = os.path.join(path, fname)
218 if not os.path.isdir(backend_path):224 if not os.path.isdir(backend_path):
219 continue225 continue
226 trace.debug(" Found backend %s" % (fname,))
220 backends.append(227 backends.append(
221 ExternalHelpersBackend(fname, backend_path))228 ExternalHelpersBackend(fname, backend_path))
222 names.add(fname)229 names.add(fname)
223230
=== modified file 'pkgme/bin/main.py'
--- pkgme/bin/main.py 2011-07-15 16:04:28 +0000
+++ pkgme/bin/main.py 2011-07-29 14:58:42 +0000
@@ -1,8 +1,11 @@
1#!/usr/bin/python
2
1import argparse3import argparse
2import os4import os
3import sys5import sys
46
5from pkgme import __version__, write_packaging7from pkgme import __version__, write_packaging
8from pkgme import trace
69
710
8def main(argv=None, target_dir=None):11def main(argv=None, target_dir=None):
@@ -14,10 +17,15 @@
14 '-v', '--version',17 '-v', '--version',
15 action='version', version='pkgme {0}'.format(__version__),18 action='version', version='pkgme {0}'.format(__version__),
16 help='Print this version string and exit')19 help='Print this version string and exit')
17 parser.parse_args(args=argv)20 parser.add_argument('-D', '--debug', action='store_true')
21 options = parser.parse_args(args=argv)
22 if options.debug:
23 trace.set_debug()
18 if target_dir is None:24 if target_dir is None:
19 target_dir = os.getcwd()25 target_dir = os.getcwd()
26 trace.debug("Building packaging for %s" % (target_dir,))
20 write_packaging(target_dir)27 write_packaging(target_dir)
28 trace.debug("Built packaging for %s" % (target_dir,))
2129
2230
23if __name__ == '__main__':31if __name__ == '__main__':
2432
=== modified file 'pkgme/project_info.py'
--- pkgme/project_info.py 2011-03-04 22:06:58 +0000
+++ pkgme/project_info.py 2011-07-29 14:58:42 +0000
@@ -1,6 +1,8 @@
1import json1import json
2from pprint import pformat
23
3from pkgme.run_script import run_script, ScriptMissing4from pkgme.run_script import run_script, ScriptMissing
5from pkgme import trace
46
57
6class ProjectInfo(object):8class ProjectInfo(object):
@@ -37,7 +39,9 @@
37 out = run_script(39 out = run_script(
38 self.basepath, self.INFO_SCRIPT_NAME, self.cwd,40 self.basepath, self.INFO_SCRIPT_NAME, self.cwd,
39 to_write=json.dumps(keys))41 to_write=json.dumps(keys))
40 return json.loads(out)42 ret = json.loads(out)
43 trace.debug('%s returned %s' % (self.INFO_SCRIPT_NAME, pformat(ret)))
44 return ret
4145
4246
43class MultipleExternalHelpersInfo(_ExternalHelpersInfo):47class MultipleExternalHelpersInfo(_ExternalHelpersInfo):
@@ -46,8 +50,11 @@
46 try:50 try:
47 out = run_script(self.basepath, key, self.cwd)51 out = run_script(self.basepath, key, self.cwd)
48 except ScriptMissing:52 except ScriptMissing:
49 return None53 ret = None
50 return out.rstrip("\n")54 else:
55 ret = out.rstrip("\n")
56 trace.debug('%s returned %s' % (key, pformat(ret)))
57 return ret
5158
52 def get_all(self, keys):59 def get_all(self, keys):
53 values = {}60 values = {}
5461
=== modified file 'pkgme/run_script.py'
--- pkgme/run_script.py 2011-04-15 19:18:29 +0000
+++ pkgme/run_script.py 2011-07-29 14:58:42 +0000
@@ -2,6 +2,8 @@
2import os2import os
3import subprocess3import subprocess
44
5from pkgme import trace
6
57
6class ScriptProblem(Exception):8class ScriptProblem(Exception):
79
@@ -38,10 +40,11 @@
38 env = os.environ.copy()40 env = os.environ.copy()
39 if os.path.isdir(helperpath):41 if os.path.isdir(helperpath):
40 if 'PATH' in env:42 if 'PATH' in env:
41 env['PATH'] = env['PATH'] + ':' + helperpath43 env['PATH'] = os.pathsep.join([env['PATH'], helperpath])
42 else:44 else:
43 env['PATH'] = helperpath45 env['PATH'] = helperpath
44 try:46 try:
47 trace.debug("Running script %s..." % (script_path,))
45 proc = subprocess.Popen(48 proc = subprocess.Popen(
46 [script_path], stdout=subprocess.PIPE,49 [script_path], stdout=subprocess.PIPE,
47 stderr=subprocess.STDOUT, stdin=subprocess.PIPE,50 stderr=subprocess.STDOUT, stdin=subprocess.PIPE,
4851
=== modified file 'pkgme/tests/test_trace.py'
--- pkgme/tests/test_trace.py 2011-07-19 14:47:30 +0000
+++ pkgme/tests/test_trace.py 2011-07-29 14:58:42 +0000
@@ -18,6 +18,7 @@
18 return temp_dir18 return temp_dir
1919
20 def with_temp_log(self):20 def with_temp_log(self):
21 self.with_temp_home()
21 self.useFixture(trace.LoggingFixture.get_default())22 self.useFixture(trace.LoggingFixture.get_default())
2223
23 def test_log_location(self):24 def test_log_location(self):
@@ -50,3 +51,28 @@
50 MatchesRegex(51 MatchesRegex(
51 r'%s - INFO - first\n%s - INFO - second\n' % (52 r'%s - INFO - first\n%s - INFO - second\n' % (
52 _date_time_re, _date_time_re)))53 _date_time_re, _date_time_re)))
54
55 def test_log_appends(self):
56 self.with_temp_log()
57 trace.log("first")
58 trace.LoggingFixture.get_default()
59 trace.log("second")
60 log_location = trace.get_log_location()
61 with open(log_location) as f:
62 log_contents = f.read()
63 self.assertThat(
64 log_contents,
65 MatchesRegex(
66 r'%s - INFO - first\n%s - INFO - second\n' % (
67 _date_time_re, _date_time_re)))
68
69 def test_set_debug(self):
70 self.with_temp_log()
71 trace.set_debug()
72 trace.debug("Hello")
73 with open(trace.get_log_location()) as f:
74 log_contents = f.read()
75 self.assertThat(
76 log_contents,
77 MatchesRegex(
78 r'%s - DEBUG - Hello\n' % (_date_time_re,)))
5379
=== modified file 'pkgme/trace.py'
--- pkgme/trace.py 2011-07-19 14:53:32 +0000
+++ pkgme/trace.py 2011-07-29 14:58:42 +0000
@@ -3,7 +3,7 @@
33
4from fixtures import Fixture4from fixtures import Fixture
55
6from pkgme.write import write_file6from pkgme.write import touch
77
88
9def get_log_location():9def get_log_location():
@@ -23,7 +23,7 @@
2323
24 def _make_handler(self):24 def _make_handler(self):
25 # Make sure that the log file exists.25 # Make sure that the log file exists.
26 write_file(self._filename, '')26 touch(self._filename)
27 handler = logging.FileHandler(self._filename)27 handler = logging.FileHandler(self._filename)
28 handler.setLevel(self._level)28 handler.setLevel(self._level)
29 formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")29 formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
@@ -54,5 +54,14 @@
54_logging_fixture.setUp()54_logging_fixture.setUp()
5555
5656
57def debug(message):
58 _logger.debug(message)
59
57def log(message):60def log(message):
58 _logger.info(message)61 _logger.info(message)
62
63
64def set_debug():
65 _logger.setLevel(logging.DEBUG)
66 for handler in _logger.handlers:
67 handler.setLevel(logging.DEBUG)
5968
=== modified file 'pkgme/write.py'
--- pkgme/write.py 2010-11-05 20:29:46 +0000
+++ pkgme/write.py 2011-07-29 14:58:42 +0000
@@ -1,10 +1,20 @@
1import os1import os
22
33
4def write_file(path, content):4def ensure_containing_directory_exists(path):
5 dirname, basename = os.path.split(path)5 dirname, basename = os.path.split(path)
6 if dirname != '' and not os.path.exists(dirname):6 if dirname != '' and not os.path.exists(dirname):
7 os.makedirs(dirname)7 os.makedirs(dirname)
8
9
10def touch(path):
11 ensure_containing_directory_exists(path)
12 with open(path, 'a'):
13 pass
14
15
16def write_file(path, content):
17 ensure_containing_directory_exists(path)
8 with open(path, "w") as f:18 with open(path, "w") as f:
9 f.write(content)19 f.write(content)
1020

Subscribers

People subscribed via source and target branches