import: Use the same extension code path we use for Morph deploy

This means logging gets its own file descriptor instead of taking over
stderr, which is probably better.

3 files changed, 81 insertions, 49 deletions

diff --git a/import/main.py b/import/main.py
index 9c83461e..67abda59 100644
--- a/import/main.py
+++ b/import/main.py
@@ -26,6 +26,7 @@ import copy
 import json
 import logging
 import os
+import sys
 import time
 
 from logging import debug
@@ -268,6 +269,43 @@ def find(iterable, match):
     return next((x for x in iterable if match(x)), None)
 
 
+def run_extension(filename, args):
+    output = []
+    errors = []
+
+    ext_logger = logging.getLogger(filename)
+
+    def report_extension_stdout(line):
+        output.append(line)
+
+    def report_extension_stderr(line):
+        errors.append(line)
+        sys.stderr.write('%s\n' % line)
+
+    def report_extension_logger(line):
+        ext_logger.debug(line)
+
+    error_list = []
+    ext = morphlib.extensions.ExtensionSubprocess(
+        report_stdout=report_extension_stdout,
+        report_stderr=report_extension_stderr,
+        report_logger=report_extension_logger,
+    )
+
+    returncode = ext.run(os.path.abspath(filename), args, '.', {})
+
+    if returncode == 0:
+        ext_logger.info('succeeded')
+    else:
+        for line in errors:
+            ext_logger.error(line)
+        message = '%s failed with code %s: %s' % (
+            filename, returncode, '\n'.join(errors))
+        raise BaserockImportException(message)
+
+    return '\n'.join(output)
+
+
 class BaserockImportApplication(cliapp.Application):
     def add_settings(self):
         self.settings.string(['lorries-dir'],
@@ -288,20 +326,12 @@ class BaserockImportApplication(cliapp.Application):
                             arg_synopsis='GEM_NAME')
 
     def setup_logging_formatter_for_file(self):
+        root_logger = logging.getLogger()
+        root_logger.name = 'main'
+
         # You need recent cliapp for this to work, with commit "Split logging
         # setup into further overrideable methods".
-        return logging.Formatter("main: %(levelname)s: %(message)s")
-
-    def setup_logging_for_import_plugins(self):
-        log = self.settings['log']
-
-        if log == '/dev/stdout':
-            # The plugins output results on /dev/stdout, logs would interfere
-            debug('Redirecting import plugin logs to /dev/stderr')
-            log = '/dev/stderr'
-
-        os.environ['BASEROCK_IMPORT_LOG'] = log
-        os.environ['BASEROCK_IMPORT_LOG_LEVEL'] = self.settings['log-level']
+        return logging.Formatter("%(name)s: %(levelname)s: %(message)s")
 
     def process_args(self, args):
         if len(args) == 0:
@@ -309,7 +339,6 @@ class BaserockImportApplication(cliapp.Application):
             # no args are passed, I prefer this.
             args = ['help']
 
-        self.setup_logging_for_import_plugins()
         super(BaserockImportApplication, self).process_args(args)
 
     def status(self, msg, *args):
@@ -384,8 +413,8 @@ class BaserockImportApplication(cliapp.Application):
         start_time = time.time()
         start_displaytime = time.strftime('%x %X %Z', time.localtime())
 
-        logging.info('Import of %s %s started %s', kind, goal_name,
-                     start_displaytime)
+        logging.info('%s: Import of %s %s started', start_displaytime, kind,
+                     goal_name)
 
         lorry_set = LorrySet(self.settings['lorries-dir'])
         morph_set = MorphologySet(self.settings['definitions-dir'])
@@ -423,7 +452,8 @@ class BaserockImportApplication(cliapp.Application):
                 runtime_deps = self.get_dependencies_from_morphology(
                     chunk_morph, 'x-runtime-dependencies-%s' % kind)
             except BaserockImportException as e:
-                self.status('%s', e)
+                # Don't print the exception on stdout; the error messages will
+                # have gone to stderr already.
                 errors[current_item] = e
                 build_deps = runtime_deps = {}
 
@@ -447,16 +477,14 @@ class BaserockImportApplication(cliapp.Application):
         duration = time.time() - start_time
         end_displaytime = time.strftime('%x %X %Z', time.localtime())
 
-        logging.info('Import of %s %s ended %s (took %i seconds)', kind,
-                     goal_name, end_displaytime, duration)
+        logging.info('%s: Import of %s %s ended (took %i seconds)',
+                     end_displaytime, kind, goal_name, duration)
+
 
     def generate_lorry_for_package(self, kind, name):
         tool = '%s.to_lorry' % kind
         self.status('Calling %s to generate lorry for %s', tool, name)
-        try:
-            lorry_text = cliapp.runcmd([os.path.abspath(tool), name])
-        except cliapp.AppException as e:
-            raise BaserockImportException(e.msg.rstrip())
+        lorry_text = run_extension(tool, [name])
         lorry = json.loads(lorry_text)
         return lorry
 
@@ -551,12 +579,7 @@ class BaserockImportApplication(cliapp.Application):
                                          filename):
         tool = '%s.to_chunk' % kind
         self.status('Calling %s to generate chunk morph for %s', tool, name)
-        try:
-            text = cliapp.runcmd(
-                [os.path.abspath(tool), source_repo.dirname, name])
-        except cliapp.AppException as e:
-            raise BaserockImportException(e.msg.rstrip())
-
+        text = run_extension(tool, [source_repo.dirname, name])
         loader = morphlib.morphloader.MorphologyLoader()
         return loader.load_from_string(text, filename)
 
diff --git a/import/rubygems.to_chunk b/import/rubygems.to_chunk
index c2b018a9..08dea123 100755
--- a/import/rubygems.to_chunk
+++ b/import/rubygems.to_chunk
@@ -27,24 +27,17 @@ require 'yaml'
 # recommended here:
 # <https://stackoverflow.com/questions/1681745/share-global-logger-among-module-classes>
 #
-log_file = ENV['BASEROCK_IMPORT_LOG'] || '/dev/null'
-
-if log_file.length == 0 then log_file = '/dev/null' end
-
-Log = Logger.new(log_file)
-
-Log.level = case ENV['BASEROCK_IMPORT_LOG_LEVEL']
-                when 'debug' then Logger::DEBUG
-                when 'warning' then Logger::WARN
-                when 'error' then Logger::ERROR
-                when 'critical', 'fatal' then Logger::FATAL
-                else Logger::INFO
-                end
-
-Log.formatter = proc do |severity, datetime, progname, msg|
-    "rubygems.to_chunk: #{severity}: #{msg}\n"
+log_fd = Integer(ENV['MORPH_LOG_FD'])
+if log_fd
+  log_stream = IO.new(log_fd, 'w')
+  Log = Logger.new(log_stream)
+  Log.level = Logger::DEBUG
+  Log.formatter = proc { |severity, datetime, progname, msg| "#{msg}\n" }
+else
+  Log = Logger.new('/dev/null')
 end
 
+
 class << Bundler
   def default_gemfile
     # This is a hack to make things not crash when there's no Gemfile
diff --git a/import/rubygems.to_lorry b/import/rubygems.to_lorry
index e345461c..da0fdc05 100755
--- a/import/rubygems.to_lorry
+++ b/import/rubygems.to_lorry
@@ -140,16 +140,32 @@ class RubyGemLorryGenerator(object):
 
 
 def setup_logging():
-    stream_name = os.environ.get('BASEROCK_IMPORT_LOG', '')
-    level = os.environ.get('BASEROCK_IMPORT_LOG_LEVEL', 'info')
+    '''Direct all logging output to MORPH_LOG_FD, if set.
 
-    level_id = logging._levelNames.get(level.upper(), logging.INFO)
-    if len(stream_name) > 0:
-        logging.basicConfig(stream=open(stream_name, 'a'), level=level_id)
+    This file descriptor is read by Morph and written into its own log
+    file.
+
+    This overrides cliapp's usual configurable logging setup.
+
+    '''
+    log_write_fd = int(os.environ.get('MORPH_LOG_FD', 0))
+
+    if log_write_fd == 0:
+        return
+
+    formatter = logging.Formatter('%(message)s')
+
+    handler = logging.StreamHandler(os.fdopen(log_write_fd, 'w'))
+    handler.setFormatter(formatter)
+
+    logger = logging.getLogger()
+    logger.addHandler(handler)
+    logger.setLevel(logging.DEBUG)
 
 
 def write_lorry(stream, lorry):
     json.dump(lorry, stream, indent=4)
+    stream.write('\n')
 
 
 def main():