Merge pull request #1016 from minrk/refine-test-env

Refine buffered output debugging

repo2docker/app.py

@@ -16,9 +16,8 @@ import getpass
 import shutil
 import tempfile
 import time
-
-from .engine import BuildError, ContainerEngineException, ImageLoadError
 from urllib.parse import urlparse
+
 import escapism
 from pythonjsonlogger import jsonlogger
 
@@ -38,6 +37,7 @@ from .buildpacks import (
     RBuildPack,
 )
 from . import contentproviders
+from .engine import BuildError, ContainerEngineException, ImageLoadError
 from .utils import ByteSpecification, chdir
 
 
@@ -629,9 +629,12 @@ class Repo2Docker(Application):
         Displaying logs while it's running
         """
 
+        last_timestamp = None
         try:
-            for line in container.logs(stream=True):
-                self.log.info(line.decode("utf-8"), extra=dict(phase="running"))
+            for line in container.logs(stream=True, timestamps=True):
+                line = line.decode("utf-8")
+                last_timestamp, line = line.split(" ", maxsplit=1)
+                self.log.info(line, extra=dict(phase="running"))
 
         finally:
             container.reload()
@@ -646,9 +649,9 @@ class Repo2Docker(Application):
                 "Container finished running.\n".upper(), extra=dict(phase="running")
             )
             # are there more logs? Let's send them back too
-            late_logs = container.logs().decode("utf-8")
+            late_logs = container.logs(since=last_timestamp).decode("utf-8")
             for line in late_logs.split("\n"):
-                self.log.info(line + "\n", extra=dict(phase="running"))
+                self.log.debug(line + "\n", extra=dict(phase="running"))
 
             container.remove()
             if exit_code:

repo2docker/docker.py

@@ -3,6 +3,8 @@ Docker container engine for repo2docker
 """
 
 import docker
+from iso8601 import parse_date
+
 from .engine import Container, ContainerEngine, ContainerEngineException, Image
 
 
@@ -13,8 +15,15 @@ class DockerContainer(Container):
     def reload(self):
         return self._c.reload()
 
-    def logs(self, *, stream=False):
-        return self._c.logs(stream=stream)
+    def logs(self, *, stream=False, timestamps=False, since=None):
+        if since:
+            # docker only accepts integer timestamps
+            # this means we will usually replay logs from the last second
+            # of the container
+            # we should check if this ever returns anything new,
+            # since we know it ~always returns something redundant
+            since = int(parse_date(since).timestamp())
+        return self._c.logs(stream=stream, timestamps=timestamps, since=since)
 
     def kill(self, *, signal="KILL"):
         return self._c.kill(signal=signal)

repo2docker/engine.py

@@ -21,7 +21,7 @@ class Container(ABC):
         """
 
     @abstractmethod
-    def logs(self, *, stream=False):
+    def logs(self, *, stream=False, timestamps=False, since=None):
         """
         Get the container logs.
 
@@ -29,6 +29,15 @@ class Container(ABC):
         ----------
         stream : bool
             If `True` return an iterator over the log lines, otherwise return all logs
+        timestamps : bool
+            If `True` log lines will be prefixed with iso8601 timestamps followed by space
+        since : str
+            A timestamp string
+            Should be in the same format as the timestamp prefix given
+            when `timestamps=True`
+
+            If given, start logs from this point,
+            instead of from container start.
 
         Returns
         -------

setup.py

@@ -50,6 +50,7 @@ setup(
         "docker",
         "entrypoints",
         "escapism",
+        "iso8601",
         "jinja2",
         "python-json-logger",
         "requests",