Merge pull request #239 from girder/log-pull

Log pull status

slicer_cli_web/image_job.py

@@ -17,6 +17,7 @@
 ###############################################################################
 
 import json
+import time
 
 import docker
 from girder import logger
@@ -159,7 +160,7 @@ def jobPullAndLoad(job):
 
         try:
             stage = 'pulling'
-            pullDockerImage(docker_client, pullList)
+            pullDockerImage(docker_client, pullList, job)
         except DockerImageNotFoundError as err:
             errorState = True
             notExistSet = set(err.imageName)
@@ -325,19 +326,57 @@ def getCliData(name, client, job):
         raise DockerImageError('Error getting %s cli data from image ' % (name) + str(err))
 
 
-def pullDockerImage(client, names):
+def pullDockerImage(client, names, job=None):
     """
     Attempt to pull the docker images listed in names. Failure results in a
     DockerImageNotFoundError being raised
 
-    :params client: The docker python client
-    :params names: A list of docker images to be pulled from the Dockerhub
+    :param client: The docker python client
+    :param names: A list of docker images to be pulled from the Dockerhub
+    :param job: A job to update with status.
     """
     imgNotExistList = []
     for name in names:
         try:
             logger.info('Pulling %s image', name)
-            client.images.pull(name)
+            lastlog = time.time()
+            stats = {}
+            for line in client.api.pull(name, stream=True, decode=True):
+                try:
+                    line.update(line.get('progressDetail', {}))
+                    if 'id' not in line or ('total' not in line and line['id'] not in stats):
+                        continue
+                    stats.setdefault(line['id'], line).update(line)
+                    if time.time() - lastlog >= 10:
+                        total = sum(record['total'] for record in stats.values())
+                        downloaded = sum(
+                            record['total'] for record in stats.values()
+                            if record['status'] != 'Downloading')
+                        downloaded += sum(
+                            record['current'] for record in stats.values()
+                            if record['status'] == 'Downloading')
+                        extracted = sum(
+                            record['total'] for record in stats.values()
+                            if record['status'] == 'Pull complete')
+                        extracted += sum(
+                            record['current'] for record in stats.values()
+                            if record['status'] == 'Extracting')
+                        if total:
+                            msg = f'Pulling {name} image: '
+                            if downloaded < total:
+                                val = downloaded
+                                msg += 'downloaded '
+                            else:
+                                val = extracted
+                                msg += 'extracted '
+                            msg += f'{val}/{total} ({val * 100 / total:4.2f}%)'
+                            logger.info(msg)
+                            if job:
+                                job = Job().updateJob(job, log=msg + '\n')
+                        lastlog = time.time()
+                except Exception:
+                    # Don't fail if the log code has an issue
+                    pass
             # some invalid image names will not be pulled but the pull method
             # will not throw an exception so the only way to confirm if a pull
             # succeeded is to attempt a docker inspect on the image