More logging

stack_orchestrator/build/build_webapp.py

@@ -27,7 +27,7 @@ from decouple import config
 import click
 from pathlib import Path
 from stack_orchestrator.build import build_containers
-from stack_orchestrator.deploy.webapp.util import determine_base_container
+from stack_orchestrator.deploy.webapp.util import determine_base_container, TimedLogger
 from stack_orchestrator.build.build_types import BuildContext
 
 
@@ -40,9 +40,11 @@ from stack_orchestrator.build.build_types import BuildContext
 @click.pass_context
 def command(ctx, base_container, source_repo, force_rebuild, extra_build_args, tag):
     '''build the specified webapp container'''
+    logger = TimedLogger()
 
     quiet = ctx.obj.quiet
     debug = ctx.obj.debug
+    verbose = ctx.obj.verbose
     local_stack = ctx.obj.local_stack
     stack = ctx.obj.stack
 
@@ -51,12 +53,12 @@ def command(ctx, base_container, source_repo, force_rebuild, extra_build_args, t
 
     if local_stack:
         dev_root_path = os.getcwd()[0:os.getcwd().rindex("stack-orchestrator")]
-        print(f'Local stack dev_root_path (CERC_REPO_BASE_DIR) overridden to: {dev_root_path}')
+        logger.log(f'Local stack dev_root_path (CERC_REPO_BASE_DIR) overridden to: {dev_root_path}')
     else:
         dev_root_path = os.path.expanduser(config("CERC_REPO_BASE_DIR", default="~/cerc"))
 
-    if not quiet:
-        print(f'Dev Root is: {dev_root_path}')
+    if verbose:
+        logger.log(f'Dev Root is: {dev_root_path}')
 
     if not base_container:
         base_container = determine_base_container(source_repo)
@@ -65,6 +67,9 @@ def command(ctx, base_container, source_repo, force_rebuild, extra_build_args, t
     container_build_env = build_containers.make_container_build_env(dev_root_path, container_build_dir, debug,
                                                                     force_rebuild, extra_build_args)
 
+    if verbose:
+        logger.log(f"Building base container: {base_container}")
+
     build_context_1 = BuildContext(
         stack,
         base_container,
@@ -74,9 +79,12 @@ def command(ctx, base_container, source_repo, force_rebuild, extra_build_args, t
     )
     ok = build_containers.process_container(build_context_1)
     if not ok:
-        print("ERROR: Build failed.", file=sys.stderr)
+        logger.log("ERROR: Build failed.")
         sys.exit(1)
 
+    if verbose:
+        logger.log(f"Base container {base_container} build finished.")
+
     # Now build the target webapp.  We use the same build script, but with a different Dockerfile and work dir.
     container_build_env["CERC_WEBAPP_BUILD_RUNNING"] = "true"
     container_build_env["CERC_CONTAINER_BUILD_WORK_DIR"] = os.path.abspath(source_repo)
@@ -85,9 +93,12 @@ def command(ctx, base_container, source_repo, force_rebuild, extra_build_args, t
                                                                           "Dockerfile.webapp")
     if not tag:
         webapp_name = os.path.abspath(source_repo).split(os.path.sep)[-1]
-        container_build_env["CERC_CONTAINER_BUILD_TAG"] = f"cerc/{webapp_name}:local"
-    else:
-        container_build_env["CERC_CONTAINER_BUILD_TAG"] = tag
+        tag = f"cerc/{webapp_name}:local"
+
+    container_build_env["CERC_CONTAINER_BUILD_TAG"] = tag
+
+    if verbose:
+        logger.log(f"Building app container: {tag}")
 
     build_context_2 = BuildContext(
         stack,
@@ -98,5 +109,9 @@ def command(ctx, base_container, source_repo, force_rebuild, extra_build_args, t
     )
     ok = build_containers.process_container(build_context_2)
     if not ok:
-        print("ERROR: Build failed.", file=sys.stderr)
-        sys.exit(1)
+        logger.log("ERROR: Build failed.")
+        sys.exit(1)
+
+    if verbose:
+        logger.log(f"App container {base_container} build finished.")
+        logger.log("build-webapp complete", show_step_time=False, show_total_time=True)

stack_orchestrator/data/container-build/cerc-nextjs-base/scripts/build-app.sh

@@ -115,7 +115,7 @@ if [ "$CERC_NEXT_VERSION" != "keep" ] && [ "$CUR_NEXT_VERSION" != "$CERC_NEXT_VE
   mv package.json.$$ package.json
 fi
 
-$CERC_BUILD_TOOL install || exit 1
+time $CERC_BUILD_TOOL install || exit 1
 
 CUR_NEXT_VERSION=`jq -r '.version' node_modules/next/package.json`
 
@@ -138,9 +138,9 @@ to use for the build with:
 EOF
   cat package.json | jq ".dependencies.next = \"^$CERC_MIN_NEXTVER\"" > package.json.$$
   mv package.json.$$ package.json
-  $CERC_BUILD_TOOL install || exit 1
+  time $CERC_BUILD_TOOL install || exit 1
 fi
 
-$CERC_BUILD_TOOL run cerc_compile || exit 1
+time $CERC_BUILD_TOOL run cerc_compile || exit 1
 
 exit 0

stack_orchestrator/data/container-build/cerc-webapp-base/scripts/build-app.sh

@@ -32,8 +32,8 @@ elif [ -f "${WORK_DIR}/package.json" ]; then
     fi
   fi
 
-  $CERC_BUILD_TOOL install || exit 1
-  $CERC_BUILD_TOOL build || exit 1
+  time $CERC_BUILD_TOOL install || exit 1
+  time $CERC_BUILD_TOOL build || exit 1
 
   rm -rf "${DEST_DIR}"
   if [ -z "${CERC_BUILD_OUTPUT_DIR}" ]; then

stack_orchestrator/deploy/webapp/deploy_webapp_from_registry.py

@@ -124,10 +124,10 @@ def process_app_deployment_request(
         else:
             extra_build_args = []  # TODO: pull from request
             logger.log(f"Building container image {deployment_container_tag}")
-            build_container_image(app, deployment_container_tag, extra_build_args, logger.file)
+            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.file)
+            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.
             logger.log(f"Updating app image tag {app_image_shared_tag} from build of {deployment_container_tag}")
@@ -140,13 +140,11 @@ def process_app_deployment_request(
 
     # 8. update k8s deployment
     if needs_k8s_deploy:
-        logger.log("Deploying to k8s")
         deploy_to_k8s(
             deployment_record,
             deployment_dir,
-            logger.file
+            logger
         )
-        logger.log("Deploy complete")
 
     logger.log("Publishing deployment to registry.")
     publish_deployment(
@@ -157,9 +155,10 @@ def process_app_deployment_request(
         dns_record,
         dns_crn,
         deployment_dir,
-        app_deployment_request
+        app_deployment_request,
+        logger
     )
-    logger.log("Publish complete.")
+    logger.log("Publication complete.")
     logger.log("END - process_app_deployment_request")
 
 

stack_orchestrator/deploy/webapp/util.py

@@ -239,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:
@@ -248,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
@@ -281,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,
@@ -312,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:
@@ -342,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 = {
@@ -361,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}