only capture logs when doing json logging

and don’t do json logging by default

log messages include newlines, carriage returns so that they can be handled correctly in terminal frontends

repo2docker/app.py

@@ -18,7 +18,7 @@ import escapism
 
 
 from traitlets.config import Application, LoggingConfigurable
-from traitlets import Type, Bool, Unicode, Dict, List
+from traitlets import Type, Bool, Unicode, Dict, List, default
 import docker
 from docker.utils import kwargs_from_env
 
@@ -40,6 +40,10 @@ class Repo2Docker(Application):
         Path to read traitlets configuration file from.
         """
     )
+    
+    @default('log_level')
+    def _default_log_level(self):
+        return logging.INFO
 
     repo = Unicode(
         os.getcwd(),
@@ -121,6 +125,13 @@ class Repo2Docker(Application):
         DANGEROUS WHEN DONE IN A CLOUD ENVIRONMENT! ONLY USE LOCALLY!
         """
     )
+    json_logs = Bool(
+        False,
+        config=True,
+        help="""
+        Enable JSON logging for easier consumption by external services.
+        """
+    )
 
     aliases = Dict({
         'repo': 'Repo2Docker.repo',
@@ -133,18 +144,21 @@ class Repo2Docker(Application):
         'no-clean': ({'Repo2Docker': {'cleanup_checkout': False}}, 'Do not clean up git checkout'),
         'no-run': ({'Repo2Docker': {'run': False}}, 'Do not run built container image'),
         'push': ({'Repo2Docker': {'push': True}}, 'Push built image to a docker registry'),
+        'json-logs': ({'Repo2Docker': {'json_logs': True}}, 'Enable JSON logging'),
     })
 
     def fetch(self, url, ref, checkout_path):
         try:
-            for line in execute_cmd(['git', 'clone', url, checkout_path]):
+            for line in execute_cmd(['git', 'clone', url, checkout_path],
+                                    capture=self.json_logs):
                 self.log.info(line, extra=dict(phase='fetching'))
         except subprocess.CalledProcessError:
             self.log.error('Failed to clone repository!', extra=dict(phase='failed'))
             sys.exit(1)
 
         try:
-            for line in execute_cmd(['git', 'reset', '--hard', ref], cwd=checkout_path):
+            for line in execute_cmd(['git', 'reset', '--hard', ref], cwd=checkout_path,
+                                    capture=self.json_logs):
                 self.log.info(line, extra=dict(phase='fetching'))
         except subprocess.CalledProcessError:
             self.log.error('Failed to check out ref %s', ref, extra=dict(phase='failed'))
@@ -152,15 +166,22 @@ class Repo2Docker(Application):
 
     def initialize(self, *args, **kwargs):
         super().initialize(*args, **kwargs)
-        logHandler = logging.StreamHandler()
-        formatter = jsonlogger.JsonFormatter()
-        logHandler.setFormatter(formatter)
-        # Need to reset existing handlers, or we repeat messages
-        self.log.handlers = []
-        self.log.addHandler(logHandler)
-        self.log.setLevel(logging.INFO)
         self.load_config_file(self.config_file)
 
+        if self.json_logs:
+            # Need to reset existing handlers, or we repeat messages
+            logHandler = logging.StreamHandler()
+            formatter = jsonlogger.JsonFormatter()
+            logHandler.setFormatter(formatter)
+            self.log.handlers = []
+            self.log.addHandler(logHandler)
+            self.log.setLevel(logging.INFO)
+        else:
+            # due to json logger stuff above,
+            # our log messages include carriage returns, newlines, etc.
+            # remove the additional newline from the stream handler
+            self.log.handlers[0].terminator = ''
+
         if len(self.extra_args) == 1:
             # accept repo as a positional arg
             self.repo = self.extra_args[0]
@@ -192,7 +213,7 @@ class Repo2Docker(Application):
             else:
                 layers[progress['id']] = progress['status']
             if time.time() - last_emit_time > 1.5:
-                self.log.info('Pushing image', extra=dict(progress=layers, phase='pushing'))
+                self.log.info('Pushing image\n', extra=dict(progress=layers, phase='pushing'))
                 last_emit_time = time.time()
 
     def run_image(self):
@@ -210,9 +231,9 @@ class Repo2Docker(Application):
 
         try:
             for line in container.logs(stream=True):
-                self.log.info(line.decode('utf-8').rstrip(), extra=dict(phase='running'))
+                self.log.info(line.decode('utf-8'), extra=dict(phase='running'))
         finally:
-            self.log.info('Stopping container...', extra=dict(phase='running'))
+            self.log.info('Stopping container...\n', extra=dict(phase='running'))
             container.kill()
             container.remove()
 
@@ -247,9 +268,9 @@ class Repo2Docker(Application):
                 checkout_path
             )
             for bp_class in self.buildpacks:
-                bp = bp_class()
+                bp = bp_class(parent=self, log=self.log, capture=self.json_logs)
                 if bp.detect(checkout_path):
-                    self.log.info('Using %s builder', bp.name, extra=dict(phase='building'))
+                    self.log.info('Using %s builder\n', bp.name, extra=dict(phase='building'))
                     bp.build(checkout_path, self.ref, self.output_image_spec)
                     break
             else:

repo2docker/detectors.py

@@ -4,7 +4,7 @@ import subprocess
 
 import docker
 
-from traitlets import Unicode, Dict
+from traitlets import Unicode, Dict, Bool
 from traitlets.config import LoggingConfigurable
 
 import logging
@@ -16,16 +16,7 @@ here = os.path.abspath(os.path.dirname(__file__))
 
 class BuildPack(LoggingConfigurable):
     name = Unicode()
-    def __init__(self, *args, **kwargs):
-        super().__init__(*args, **kwargs)
-        # FIXME: Not sure why this needs to be repeated - shouldn't configuring Application be enough?
-        logHandler = logging.StreamHandler()
-        formatter = jsonlogger.JsonFormatter()
-        logHandler.setFormatter(formatter)
-        # Need to reset existing handlers, or we repeat messages
-        self.log.handlers = []
-        self.log.addHandler(logHandler)
-        self.log.setLevel(logging.INFO)
+    capture = Bool(False, help="Capture output for logging")
 
     def detect(self, workdir):
         """
@@ -53,7 +44,7 @@ class DockerBuildPack(BuildPack):
                 decode=True
         ):
             if 'stream' in progress:
-                self.log.info(progress['stream'].rstrip(), extra=dict(phase='building'))
+                self.log.info(progress['stream'], extra=dict(phase='building'))
 
 
 class S2IBuildPack(BuildPack):
@@ -79,7 +70,7 @@ class S2IBuildPack(BuildPack):
         # in case user doesn't have s2i
         env['PATH'] = os.pathsep.join([env.get('PATH') or os.defpath, here])
         try:
-            for line in execute_cmd(cmd, cwd=workdir, env=env):
+            for line in execute_cmd(cmd, cwd=workdir, env=env, capture=self.capture):
                 self.log.info(line, extra=dict(phase='building', builder=self.name))
         except subprocess.CalledProcessError:
             self.log.error('Failed to build image!', extra=dict(phase='failed'))

repo2docker/utils.py

@@ -1,14 +1,24 @@
 import subprocess
 
-def execute_cmd(cmd, **kwargs):
+def execute_cmd(cmd, capture=False, **kwargs):
     """
-    Call given command, yielding output line by line
+    Call given command, yielding output line by line if capture=True
     """
-    proc = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, universal_newlines=True, **kwargs)
+    if capture:
+        kwargs['stdout'] = subprocess.PIPE
+        kwargs['stderr'] = subprocess.STDOUT
+
+    proc = subprocess.Popen(cmd, **kwargs)
+
+    if not capture:
+        ret = proc.wait()
+        if ret != 0:
+            raise subprocess.CalledProcessError(ret, cmd)
+        return
 
     try:
-        for line in iter(proc.stdout.readline, ''):
-            yield line.rstrip()
+        for line in iter(proc.stdout.readline, b''):
+            yield line.decode('utf8', 'replace')
     finally:
         ret = proc.wait()
         if ret != 0: