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

[Jonathan Lange]

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.

[Jonathan Lange (jml)]

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...

[James Westby (james-w)]

review: Approve

=== 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 @@
 [DEFAULT]
-test_command=python -m subunit.run $IDLIST
+test_command=PYTHONPATH=`pwd` python -m subunit.run $IDLIST
 test_id_list_default=pkgme.tests.test_suite

=== 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 @@
     SingleExternalHelperInfo,
     )
 from pkgme.run_script import run_script, ScriptMissing
+from pkgme import trace
 
 
 def get_backend_dir(underunder_file, backend):
@@ -173,8 +174,10 @@
     def get_info(self, path):
         high_score = 0
         eligble = []
+        trace.debug('Finding backend for %s' % (path,))
         for backend in self.backends:
             score = backend.want(path)
+            trace.debug('  %s scored %s' % (backend.name, score))
             if score > high_score:
                 eligble = [backend]
                 high_score = score
@@ -187,6 +190,8 @@
         if len(eligble) > 1:
             eligble.sort(key=attrgetter('name'))
             backend = eligble[0]
+            trace.debug(
+                '%s eligble backends. Picked %s' % (len(eligble), backend.name))
         return backend.get_info(path)
 
 
@@ -205,6 +210,7 @@
         backends = []
         names = set()
         for path in self.paths:
+            trace.debug("Loading backends from: %s" % (path,))
             path = os.path.abspath(path)
             if not os.path.isdir(path):
                 continue
@@ -217,6 +223,7 @@
                 backend_path = os.path.join(path, fname)
                 if not os.path.isdir(backend_path):
                     continue
+                trace.debug("  Found backend %s" % (fname,))
                 backends.append(
                     ExternalHelpersBackend(fname, backend_path))
                 names.add(fname)

=== 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 @@
+#!/usr/bin/python
+
 import argparse
 import os
 import sys
 
 from pkgme import __version__, write_packaging
+from pkgme import trace
 
 
 def main(argv=None, target_dir=None):
@@ -14,10 +17,15 @@
         '-v', '--version',
         action='version', version='pkgme {0}'.format(__version__),
         help='Print this version string and exit')
-    parser.parse_args(args=argv)
+    parser.add_argument('-D', '--debug', action='store_true')
+    options = parser.parse_args(args=argv)
+    if options.debug:
+        trace.set_debug()
     if target_dir is None:
         target_dir = os.getcwd()
+    trace.debug("Building packaging for %s" % (target_dir,))
     write_packaging(target_dir)
+    trace.debug("Built packaging for %s" % (target_dir,))
 
 
 if __name__ == '__main__':

=== 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 @@
 import json
+from pprint import pformat
 
 from pkgme.run_script import run_script, ScriptMissing
+from pkgme import trace
 
 
 class ProjectInfo(object):
@@ -37,7 +39,9 @@
         out = run_script(
             self.basepath, self.INFO_SCRIPT_NAME, self.cwd,
             to_write=json.dumps(keys))
-        return json.loads(out)
+        ret = json.loads(out)
+        trace.debug('%s returned %s' % (self.INFO_SCRIPT_NAME, pformat(ret)))
+        return ret
 
 
 class MultipleExternalHelpersInfo(_ExternalHelpersInfo):
@@ -46,8 +50,11 @@
         try:
             out = run_script(self.basepath, key, self.cwd)
         except ScriptMissing:
-            return None
-        return out.rstrip("\n")
+            ret = None
+        else:
+            ret = out.rstrip("\n")
+        trace.debug('%s returned %s' % (key, pformat(ret)))
+        return ret
 
     def get_all(self, keys):
         values = {}

=== 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 @@
 import os
 import subprocess
 
+from pkgme import trace
+
 
 class ScriptProblem(Exception):
 
@@ -38,10 +40,11 @@
     env = os.environ.copy()
     if os.path.isdir(helperpath):
         if 'PATH' in env:
-            env['PATH'] = env['PATH'] + ':' + helperpath
+            env['PATH'] = os.pathsep.join([env['PATH'], helperpath])
         else:
             env['PATH'] = helperpath
     try:
+        trace.debug("Running script %s..." % (script_path,))
         proc = subprocess.Popen(
             [script_path], stdout=subprocess.PIPE,
             stderr=subprocess.STDOUT, stdin=subprocess.PIPE,

=== 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 @@
         return temp_dir
 
     def with_temp_log(self):
+        self.with_temp_home()
         self.useFixture(trace.LoggingFixture.get_default())
 
     def test_log_location(self):
@@ -50,3 +51,28 @@
             MatchesRegex(
                 r'%s - INFO - first\n%s - INFO - second\n' % (
                     _date_time_re, _date_time_re)))
+
+    def test_log_appends(self):
+        self.with_temp_log()
+        trace.log("first")
+        trace.LoggingFixture.get_default()
+        trace.log("second")
+        log_location = trace.get_log_location()
+        with open(log_location) as f:
+            log_contents = f.read()
+        self.assertThat(
+            log_contents,
+            MatchesRegex(
+                r'%s - INFO - first\n%s - INFO - second\n' % (
+                    _date_time_re, _date_time_re)))
+
+    def test_set_debug(self):
+        self.with_temp_log()
+        trace.set_debug()
+        trace.debug("Hello")
+        with open(trace.get_log_location()) as f:
+            log_contents = f.read()
+        self.assertThat(
+            log_contents,
+            MatchesRegex(
+                r'%s - DEBUG - Hello\n' % (_date_time_re,)))

=== 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 @@
 
 from fixtures import Fixture
 
-from pkgme.write import write_file
+from pkgme.write import touch
 
 
 def get_log_location():
@@ -23,7 +23,7 @@
 
     def _make_handler(self):
         # Make sure that the log file exists.
-        write_file(self._filename, '')
+        touch(self._filename)
         handler = logging.FileHandler(self._filename)
         handler.setLevel(self._level)
         formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
@@ -54,5 +54,14 @@
 _logging_fixture.setUp()
 
 
+def debug(message):
+    _logger.debug(message)
+
 def log(message):
     _logger.info(message)
+
+
+def set_debug():
+    _logger.setLevel(logging.DEBUG)
+    for handler in _logger.handlers:
+        handler.setLevel(logging.DEBUG)

=== 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 @@
 import os
 
 
-def write_file(path, content):
+def ensure_containing_directory_exists(path):
     dirname, basename = os.path.split(path)
     if dirname != '' and not os.path.exists(dirname):
         os.makedirs(dirname)
+
+
+def touch(path):
+    ensure_containing_directory_exists(path)
+    with open(path, 'a'):
+        pass
+
+
+def write_file(path, content):
+    ensure_containing_directory_exists(path)
     with open(path, "w") as f:
         f.write(content)