Add timed logging for the webapp build (#771)

Add lots of log and timer output to webapp builds.

Reviewed-on: #771

stack_orchestrator/deploy/webapp/deploy_webapp_from_registry.py

@@ -26,7 +26,7 @@ import click
 
 from stack_orchestrator.deploy.images import remote_image_exists, add_tags_to_image
 from stack_orchestrator.deploy.webapp import deploy_webapp
-from stack_orchestrator.deploy.webapp.util import (LaconicRegistryClient,
+from stack_orchestrator.deploy.webapp.util import (LaconicRegistryClient, TimedLogger,
                                                    build_container_image, push_container_image,
                                                    file_hash, deploy_to_k8s, publish_deployment,
                                                    hostname_for_deployment_request, generate_hostname_for_app,
@@ -34,7 +34,6 @@ from stack_orchestrator.deploy.webapp.util import (LaconicRegistryClient,
 
 
 def process_app_deployment_request(
-    run_id,
     ctx,
     laconic: LaconicRegistryClient,
     app_deployment_request,
@@ -44,14 +43,18 @@ def process_app_deployment_request(
     deployment_parent_dir,
     kube_config,
     image_registry,
-    force_rebuild=False,
-    log_file=None
+    force_rebuild,
+    logger
 ):
+    logger.log("BEGIN - process_app_deployment_request")
+
     # 1. look up application
     app = laconic.get_record(app_deployment_request.attributes.application, require=True)
+    logger.log(f"Retrieved app record {app_deployment_request.attributes.application}")
 
     # 2. determine dns
     requested_name = hostname_for_deployment_request(app_deployment_request, laconic)
+    logger.log(f"Determined requested name: {requested_name}")
 
     # HACK
     if "." in requested_name:
@@ -69,7 +72,7 @@ def process_app_deployment_request(
             matched_owner = match_owner(app_deployment_request, laconic.get_record(dns_record.attributes.request, require=True))
 
         if matched_owner:
-            print("Matched DnsRecord ownership:", matched_owner)
+            logger.log(f"Matched DnsRecord ownership: {matched_owner}")
         else:
             raise Exception("Unable to confirm ownership of DnsRecord %s for request %s" %
                             (dns_record.id, app_deployment_request.id))
@@ -115,15 +118,21 @@ def process_app_deployment_request(
         shared_tag_exists = remote_image_exists(image_registry, app_image_shared_tag)
         if shared_tag_exists and not force_rebuild:
             # simply add our unique tag to the existing image and we are done
-            print(f"Using existing app image {app_image_shared_tag} for {deployment_container_tag}", file=log_file)
+            logger.log(f"Using existing app image {app_image_shared_tag} for {deployment_container_tag}")
             add_tags_to_image(image_registry, app_image_shared_tag, deployment_container_tag)
+            logger.log("Tag complete")
         else:
             extra_build_args = []  # TODO: pull from request
-            build_container_image(app, deployment_container_tag, extra_build_args, log_file)
-            push_container_image(deployment_dir, log_file)
+            logger.log(f"Building container image {deployment_container_tag}")
+            build_container_image(app, deployment_container_tag, extra_build_args, logger)
+            logger.log("Build complete")
+            logger.log(f"Pushing container image {deployment_container_tag}")
+            push_container_image(deployment_dir, logger)
+            logger.log("Push complete")
             # The build/push commands above will use the unique deployment tag, so now we need to add the shared tag.
-            print(f"Updating app image tag {app_image_shared_tag} from build of {deployment_container_tag}", file=log_file)
+            logger.log(f"Updating app image tag {app_image_shared_tag} from build of {deployment_container_tag}")
             add_tags_to_image(image_registry, deployment_container_tag, app_image_shared_tag)
+            logger.log("Tag complete")
 
     # 7. update config (if needed)
     if not deployment_record or file_hash(deployment_config_file) != deployment_record.attributes.meta.config:
@@ -131,13 +140,13 @@ def process_app_deployment_request(
 
     # 8. update k8s deployment
     if needs_k8s_deploy:
-        print("Deploying to k8s")
         deploy_to_k8s(
             deployment_record,
             deployment_dir,
-            log_file
+            logger
         )
 
+    logger.log("Publishing deployment to registry.")
     publish_deployment(
         laconic,
         app,
@@ -146,8 +155,11 @@ def process_app_deployment_request(
         dns_record,
         dns_crn,
         deployment_dir,
-        app_deployment_request
+        app_deployment_request,
+        logger
     )
+    logger.log("Publication complete.")
+    logger.log("END - process_app_deployment_request")
 
 
 def load_known_requests(filename):
@@ -309,8 +321,9 @@ def command(ctx, kube_config, laconic_config, image_registry, deployment_parent_
                     run_log_file = open(run_log_file_path, "wt")
                     run_reg_client = LaconicRegistryClient(laconic_config, log_file=run_log_file)
 
+                logger = TimedLogger(run_id, run_log_file)
+                logger.log("Processing ...")
                 process_app_deployment_request(
-                    run_id,
                     ctx,
                     run_reg_client,
                     r,
@@ -321,12 +334,14 @@ def command(ctx, kube_config, laconic_config, image_registry, deployment_parent_
                     kube_config,
                     image_registry,
                     force_rebuild,
-                    run_log_file
+                    logger
                 )
                 status = "DEPLOYED"
             except Exception as e:
-                print("ERROR: " + str(e), file=run_log_file)
+                logger.log("ERROR: " + str(e))
             finally:
+                if logger:
+                    logger.log(f"DONE with status {status}", show_step_time=False, show_total_time=True)
                 dump_known_requests(state_file, [r], status)
                 if run_log_file:
                     run_log_file.close()

stack_orchestrator/deploy/webapp/util.py

@@ -13,6 +13,7 @@
 # You should have received a copy of the GNU Affero General Public License
 # along with this program.  If not, see <http:#www.gnu.org/licenses/>.
 
+import datetime
 import hashlib
 import json
 import os
@@ -39,6 +40,25 @@ class AttrDict(dict):
             return v
 
 
+class TimedLogger:
+    def __init__(self, id="", file=None):
+        self.start = datetime.datetime.now()
+        self.last = self.start
+        self.id = id
+        self.file = file
+
+    def log(self, msg, show_step_time=True, show_total_time=False):
+        prefix = f"{datetime.datetime.utcnow()} - {self.id}"
+        if show_step_time:
+            prefix += f" - {datetime.datetime.now() - self.last} (step)"
+        if show_total_time:
+            prefix += f" - {datetime.datetime.now() - self.start} (total)"
+        print(f"{prefix}: {msg}", file=self.file)
+        if self.file:
+            self.file.flush()
+        self.last = datetime.datetime.now()
+
+
 def logged_cmd(log_file, *vargs):
     result = None
     try:
@@ -219,7 +239,7 @@ def determine_base_container(clone_dir, app_type="webapp"):
     return base_container
 
 
-def build_container_image(app_record, tag, extra_build_args=[], log_file=None):
+def build_container_image(app_record, tag, extra_build_args=[], logger=None):
     tmpdir = tempfile.mkdtemp()
 
     try:
@@ -228,31 +248,33 @@ def build_container_image(app_record, tag, extra_build_args=[], log_file=None):
         repo = random.choice(app_record.attributes.repository)
         clone_dir = os.path.join(tmpdir, record_id)
 
-        print(f"Cloning repository {repo} to {clone_dir} ...")
+        logger.log(f"Cloning repository {repo} to {clone_dir} ...")
         if ref:
             # TODO: Determing branch or hash, and use depth 1 if we can.
             git_env = dict(os.environ.copy())
             # Never prompt
             git_env["GIT_TERMINAL_PROMPT"] = "0"
             try:
-                subprocess.check_call(["git", "clone", repo, clone_dir], env=git_env, stdout=log_file, stderr=log_file)
+                subprocess.check_call(["git", "clone", repo, clone_dir], env=git_env, stdout=logger.file, stderr=logger.file)
             except Exception as e:
-                print(f"git clone failed.  Is the repository {repo} private?", file=log_file)
+                logger.log(f"git clone failed.  Is the repository {repo} private?")
                 raise e
             try:
-                subprocess.check_call(["git", "checkout", ref], cwd=clone_dir, env=git_env, stdout=log_file, stderr=log_file)
+                subprocess.check_call(["git", "checkout", ref], cwd=clone_dir, env=git_env, stdout=logger.file, stderr=logger.file)
             except Exception as e:
-                print(f"git checkout failed.  Does ref {ref} exist?", file=log_file)
+                logger.log(f"git checkout failed.  Does ref {ref} exist?")
                 raise e
         else:
-            result = subprocess.run(["git", "clone", "--depth", "1", repo, clone_dir], stdout=log_file, stderr=log_file)
+            result = subprocess.run(["git", "clone", "--depth", "1", repo, clone_dir], stdout=logger.file, stderr=logger.file)
             result.check_returncode()
 
         base_container = determine_base_container(clone_dir, app_record.attributes.app_type)
 
-        print("Building webapp ...")
+        logger.log("Building webapp ...")
         build_command = [
-            sys.argv[0], "build-webapp",
+            sys.argv[0],
+            "--verbose",
+            "build-webapp",
             "--source-repo", clone_dir,
             "--tag", tag,
             "--base-container", base_container
@@ -261,28 +283,31 @@ def build_container_image(app_record, tag, extra_build_args=[], log_file=None):
             build_command.append("--extra-build-args")
             build_command.append(" ".join(extra_build_args))
 
-        result = subprocess.run(build_command, stdout=log_file, stderr=log_file)
+        result = subprocess.run(build_command, stdout=logger.file, stderr=logger.file)
         result.check_returncode()
     finally:
-        logged_cmd(log_file, "rm", "-rf", tmpdir)
+        logged_cmd(logger.file, "rm", "-rf", tmpdir)
 
 
-def push_container_image(deployment_dir, log_file=None):
-    print("Pushing image ...")
+def push_container_image(deployment_dir, logger):
+    logger.log("Pushing images ...")
     result = subprocess.run([sys.argv[0], "deployment", "--dir", deployment_dir, "push-images"],
-                            stdout=log_file, stderr=log_file)
+                            stdout=logger.file, stderr=logger.file)
     result.check_returncode()
+    logger.log("Finished pushing images.")
 
 
-def deploy_to_k8s(deploy_record, deployment_dir, log_file=None):
+def deploy_to_k8s(deploy_record, deployment_dir, logger):
     if not deploy_record:
         command = "up"
     else:
         command = "update"
 
+    logger.log("Deploying to k8s ...")
     result = subprocess.run([sys.argv[0], "deployment", "--dir", deployment_dir, command],
-                            stdout=log_file, stderr=log_file)
+                            stdout=logger.file, stderr=logger.file)
     result.check_returncode()
+    logger.log("Finished deploying to k8s.")
 
 
 def publish_deployment(laconic: LaconicRegistryClient,
@@ -292,7 +317,8 @@ def publish_deployment(laconic: LaconicRegistryClient,
                        dns_record,
                        dns_crn,
                        deployment_dir,
-                       app_deployment_request=None):
+                       app_deployment_request=None,
+                       logger=None):
     if not deploy_record:
         deploy_ver = "0.0.1"
     else:
@@ -322,6 +348,8 @@ def publish_deployment(laconic: LaconicRegistryClient,
     if app_deployment_request:
         new_dns_record["record"]["request"] = app_deployment_request.id
 
+    if logger:
+        logger.log("Publishing DnsRecord.")
     dns_id = laconic.publish(new_dns_record, [dns_crn])
 
     new_deployment_record = {
@@ -341,6 +369,8 @@ def publish_deployment(laconic: LaconicRegistryClient,
     if app_deployment_request:
         new_deployment_record["record"]["request"] = app_deployment_request.id
 
+    if logger:
+        logger.log("Publishing ApplicationDeploymentRecord.")
     deployment_id = laconic.publish(new_deployment_record, [deployment_crn])
     return {"dns": dns_id, "deployment": deployment_id}