separate logs and only reveal progress in console (#14)

CelestaLiu · web-flow · commit 5a48ce37c614 · 2025-07-30T14:16:06.000+01:00
* separate logs and only reveal progress in console

* add details in log
diff --git a/build.py b/build.py
@@ -1,15 +1,14 @@
 import os
 import sys
 import subprocess
+import logging
+from utils import run_command
 
-def run_command(cmd, **kwargs):
-    print("[CMD]", " ".join(cmd))
-    subprocess.run(cmd, check=True, **kwargs)
-
-def build_sqlancer_image(force_rebuild=False):
+def build_sqlancer_image(script_log, docker_log, force_rebuild=False):
     if force_rebuild:
-        print("[INFO] Rebuilding SQLancer image due to --cache not specified...")
-        run_command(["docker", "build", "--no-cache", "-t", "sqlancer:latest", "./sqlancer"])
+        script_log.info("Rebuilding SQLancer image: sqlancer:latest ...")
+        run_command(["docker", "build", "--no-cache", "-t", "sqlancer:latest", "./sqlancer"], docker_log)
+        script_log.info("SQLancer image built: sqlancer:latest")
         return
 
     result = subprocess.run(
@@ -18,12 +17,13 @@ def build_sqlancer_image(force_rebuild=False):
     )
     images = result.stdout.strip().splitlines()
     if "sqlancer:latest" in images:
-        print("[INFO] SQLancer image already exists: sqlancer:latest")
+        script_log.info("SQLancer image exists: sqlancer:latest")
     else:
-        print("[INFO] SQLancer image not found. Building from ./sqlancer...")
-        run_command(["docker", "build", "-t", "sqlancer:latest", "./sqlancer"])
+        script_log.info("Building SQLancer image from cache: sqlancer:latest...")
+        run_command(["docker", "build", "-t", "sqlancer:latest", "./sqlancer"], docker_log)
+        script_log.info("SQLancer image built: sqlancer:latest")
 
-def build_network(network_name="sqlancer-net"):
+def build_network(script_log, docker_log, network_name="sqlancer-net"):
     try:
         output = subprocess.check_output([
             "docker", "network", "ls",
@@ -32,29 +32,37 @@ def build_network(network_name="sqlancer-net"):
         ])
         networks = output.decode().splitlines()
         if network_name not in networks:
-            print(f"[INFO] Creating docker network: {network_name}")
-            subprocess.run(["docker", "network", "create", network_name], check=True)
+            script_log.info("Building network: %s ...", network_name)
+            run_command(["docker", "network", "create", network_name], docker_log)
+            script_log.info("Network built: %s", network_name)
         else:
-            print(f"[INFO] Docker network '{network_name}' already exists.")
+            script_log.info("Network already exists: %s", network_name)
+            
     except Exception as e:
-        print(f"[ERROR] Failed to check/create Docker network: {e}")
+        script_log.error("Network building failed: %s", network_name)
         sys.exit(1)
 
-def build_db_image(cfg, use_cache, custom=False, dockerfile_path=""):
+def build_db_image(cfg, use_cache, script_log, docker_log, custom=False, dockerfile_path=""):
     if not use_cache and not custom:
         image = cfg["image"]
-        print(f"[INFO] Pulling image {image}")
-        run_command(["docker", "pull", image])
-
-    if custom:
+        script_log.info("Pulling db image: %s ...", image)
+        run_command(["docker", "pull", image], docker_log)
+        script_log.info("DB image pulled: %s", image)
+    elif custom:
         build_cmd = ["docker", "build", "-t", cfg["image"], os.path.dirname(dockerfile_path)]
         if not use_cache:
             build_cmd.insert(2, "--no-cache")
-        run_command(build_cmd)
+        script_log.info("Building db image: %s ...", cfg["image"])
+        run_command(build_cmd, docker_log)
+        script_log.info("DB image pulled: %s ...", cfg["image"])
+    else:
+        script_log.info("DB image already exists: %s", cfg["image"])
 
-def build_environment(cfg, use_cache, custom=False, dockerfile_path=""):
-    build_network()
-    build_sqlancer_image(force_rebuild=not use_cache)
+def build_environment(cfg, use_cache, script_log, docker_log, custom=False, dockerfile_path=""):
+    script_log.info("==============================Building environment==============================")
+    build_network(script_log, docker_log)
+    build_sqlancer_image(script_log, docker_log, force_rebuild=not use_cache)
     if cfg["embedded"] == "no":
-        build_db_image(cfg, use_cache, custom, dockerfile_path)
-    
+        build_db_image(cfg, use_cache, script_log, docker_log, custom, dockerfile_path)
+    script_log.info("==============================Building environment==============================")
+    
diff --git a/sqlancer/entrypoint.sh b/sqlancer/entrypoint.sh
@@ -9,7 +9,7 @@ echo "Waiting for DB to become healthy..."
 
 cd /root/sqlancer/target || { echo "Missing target directory"; exit 1; }
 
-# Wait for the DB container (identified by SQLANCER_HOST) to become healthy
+# Wait for the DB container to become healthy
 for i in {1..60}; do
   STATUS=$(docker inspect --format='{{.State.Health.Status}}' "$SQLANCER_HOST" 2>/dev/null || echo "unknown")
   if [ "$STATUS" = "healthy" ]; then
@@ -18,13 +18,12 @@ for i in {1..60}; do
   sleep 1
 done
 
-# Prepare the command string
 CMD="java -jar sqlancer-*.jar --num-threads \"$SQLANCER_THREADS\" --timeout-seconds \"$SQLANCER_TIMEOUT\" --username \"$SQLANCER_USERNAME\" --password \"$SQLANCER_PASSWORD\" --host \"$SQLANCER_HOST\" \"$SQLANCER_DBMS\" --oracle \"$SQLANCER_ORACLE\""
 
-# Print command to console and log file
+# Show command to console + log file
 echo "Running: $CMD" | tee -a "$LOG_FILE"
 
-# Run the command and tee output to both console and log file
-eval "$CMD" 2>&1 | tee -a "$LOG_FILE"
+# Run command: log everything, show only stats to console
+eval "$CMD" 2>&1 | tee -a "$LOG_FILE" | grep --line-buffered "Executed"
 
 echo "[INFO] SQLancer finished. Logs saved to $LOG_DIR"
diff --git a/start.py b/start.py
@@ -5,6 +5,8 @@
 import json
 from test import test_single, test_custom_dockerfile
 from build import build_environment, build_sqlancer_image, build_db_image
+from utils import setup_logging
+import logging
 
 def load_json(path):
     with open(path) as f:
@@ -32,52 +34,54 @@ def main():
     global_cfg = load_json("config.json")
     dbms_list = global_cfg.get("dbms_list", [])
 
+    script_log, docker_log, sqlancer_log, run_dir = setup_logging()
+    script_log.info("Log output directory: %s", run_dir)
+
     if args.command == "test":
         if args.dockerfile:
             if not args.config:
                 parser.error("Custom DBMS test requires --config")
             cfg = load_json(args.config)
-            build_environment(cfg, use_cache, True, args.dockerfile)
-            test_custom_dockerfile(args.dockerfile, cfg, use_cache)
+            build_environment(cfg, use_cache, script_log, docker_log, True, args.dockerfile)
+            test_custom_dockerfile(args.dockerfile, cfg, script_log, docker_log, sqlancer_log, run_dir, use_cache)
 
         elif args.dbms == "all":
             for dbms in dbms_list:
                 config_path = os.path.join(dbms, "config.json")
                 if not os.path.exists(config_path):
-                    print(f"[WARNING] Skipping {dbms}, missing config file.")
+                    # print(f"[WARNING] Skipping {dbms}, missing config file.")
                     continue
                 cfg = load_json(config_path)
-                build_environment(cfg, use_cache)
-                test_single(cfg, use_cache)
+                build_environment(cfg, use_cache, script_log, docker_log)
+                test_single(cfg, script_log, docker_log, sqlancer_log, run_dir, use_cache)
 
         elif args.dbms:
             if not args.config:
                 parser.error("Single DBMS test requires --config")
             cfg = load_json(args.config)
-            build_environment(cfg, use_cache)
-            test_single(cfg, use_cache)
-
+            build_environment(cfg, use_cache, script_log, docker_log)
+            test_single(cfg, script_log, docker_log, sqlancer_log, run_dir, use_cache)
         else:
             parser.error("Must specify either --dbms or --dockerfile")
     elif args.command == "build":
         if args.sqlancer:
-            build_sqlancer_image(not use_cache)
+            build_sqlancer_image(script_log, docker_log, not use_cache)
 
         elif args.dbms == "all":
             for dbms in dbms_list:
                 config_path = os.path.join(dbms, "config.json")
                 if not os.path.exists(config_path):
-                    print(f"[WARNING] Skipping {dbms}, missing config file.")
+                    # print(f"[WARNING] Skipping {dbms}, missing config file.")
                     continue
                 cfg = load_json(config_path)
-                build_db_image(cfg, use_cache)
+                build_db_image(cfg, use_cache, script_log, docker_log)
         elif args.dbms:
             config_path = os.path.join(args.dbms, "config.json")
             if not os.path.exists(config_path):
-                print(f"[ERROR] Config file not found for DBMS: {args.dbms}")
+                # print(f"[ERROR] Config file not found for DBMS: {args.dbms}")
                 sys.exit(1)
             cfg = load_json(config_path)
-            build_db_image(cfg, use_cache)
+            build_db_image(cfg, use_cache, script_log, docker_log)
 
         else:
             parser.error("Must specify --dbms or --sqlancer for build command")
diff --git a/test.py b/test.py
@@ -5,10 +5,7 @@
 import time
 import shlex
 from datetime import datetime
-
-def run_command(cmd, **kwargs):
-    print("[CMD]", " ".join(cmd))
-    subprocess.run(cmd, check=True, **kwargs)
+from utils import run_command
 
 def container_exists(name):
     result = subprocess.run(
@@ -17,18 +14,18 @@ def container_exists(name):
     )
     return name in result.stdout.strip().splitlines()
 
-def start_db_container(dbms, cfg):
+def start_db_container(dbms, cfg, script_log, docker_log):
     image = cfg.get("image")
     container_name = cfg.get("container_name", f"{dbms}-sqlancer")
     env_dict = cfg.get("env", {})
 
     if not image:
-        print("[ERROR] Missing 'image' field in config.json")
+        script_log.error( "Missing 'image' field in config.json")
         sys.exit(1)
 
     if container_exists(container_name):
-        print(f"[INFO] Container '{container_name}' already exists. Remove the old container and restart.")
-        remove_container(container_name)
+        script_log.info( "Container %s already exists, remove the old container and restart", container_name)
+        remove_container(container_name, script_log, docker_log)
 
     env_vars = []
     for k, v in env_dict.items():
@@ -40,13 +37,12 @@ def start_db_container(dbms, cfg):
         "--network", "sqlancer-net",
         *env_vars,
         image
-    ])
-
+    ], docker_log)
 
-    print(f"[INFO] Waiting for DBMS container '{container_name}' to be ready...")
+    script_log.info("Starting DBMS container: %s ...", container_name)
     time.sleep(10)
 
-    # Optional init SQL
+    
     init_sql = cfg.get("init_sql")
     init_cmd_template = cfg.get("init_sql_command_template")
     if init_sql and init_cmd_template:
@@ -57,18 +53,22 @@ def start_db_container(dbms, cfg):
                 sql=init_sql
             )
             full_cmd = ["docker", "exec", container_name] + shlex.split(cmd_str)
-            print(f"[INFO] Running init SQL inside container: {init_sql}")
-            run_command(full_cmd)
+            script_log.info("Running init SQL inside container...")
+            run_command(full_cmd, docker_log)
         except Exception as e:
-            print(f"[WARNING] Failed to run init SQL: {e}")
+            script_log.warning("Init SQL running failed")
 
-def start_sqlancer_container(dbms, host_container_name, username, password, oracle, threads, timeout):
-    date = datetime.today().strftime("%y-%m-%d-%H-%M-%S")  
-    log_dir_host = os.path.abspath(os.path.join("logs", date))
-    os.makedirs(log_dir_host, exist_ok=True)
+    script_log.info("DBMS container started: %s", container_name)
+
+def start_sqlancer_container(dbms, host_container_name, username, password, oracle, threads, timeout, script_log, docker_log, sqlancer_log, run_dir):
+    cmd = f"java -jar sqlancer-*.jar --num-threads {threads} --timeout-seconds {timeout} --username {username} --password {password} --host {host_container_name} {dbms} --oracle {oracle}"
+    script_log.info("Executing test: %s", cmd)
+    # date = datetime.today().strftime("%y-%m-%d-%H-%M-%S")  
+    # log_dir_host = os.path.abspath(os.path.join("logs", date))
+    # os.makedirs(log_dir_host, exist_ok=True)
 
-    run_log_container_dir = "/logs"
-    sqlancer_logs_container_dir = "/root/sqlancer/target/logs"
+    log_dir_host = os.path.abspath(run_dir)
+    os.makedirs(log_dir_host, exist_ok=True)
 
     run_command([
         "docker", "run", "--rm",
@@ -81,15 +81,17 @@ def start_sqlancer_container(dbms, host_container_name, username, password, orac
         "-e", f"SQLANCER_ORACLE={oracle}",
         "-e", f"SQLANCER_THREADS={threads}",
         "-e", f"SQLANCER_TIMEOUT={timeout}",
-        "-v", f"{log_dir_host}:{run_log_container_dir}",
-        "-v", f"{log_dir_host}:{sqlancer_logs_container_dir}",
+        # "-v", f"{log_dir_host}:/logs",
+        "-v", f"{log_dir_host}:/root/sqlancer/target/logs",
         "sqlancer:latest"
-    ])
+    ], sqlancer_log)
+    script_log.info("Test executed")
 
 
-def test_single(cfg, use_cache=False):
+def test_single(cfg, script_log, docker_log, sqlancer_log, run_dir, use_cache=False):
+    script_log.info("==============================Executing test==============================")
     if cfg["embedded"] == "no":
-        start_db_container(cfg["dbms"], cfg)
+        start_db_container(cfg["dbms"], cfg, script_log, docker_log)
 
     start_sqlancer_container(
         dbms=cfg["dbms"],
@@ -98,36 +100,46 @@ def test_single(cfg, use_cache=False):
         password=cfg["password"],
         oracle=cfg["oracle"],
         threads=cfg["num_threads"],
-        timeout=cfg["timeout_seconds"]
+        timeout=cfg["timeout_seconds"],
+        script_log=script_log,
+        sqlancer_log=sqlancer_log,
+        docker_log=docker_log,
+        run_dir=run_dir
     )
 
     if cfg["embedded"] == "no":
-        remove_container(cfg["container_name"])
+        remove_container(cfg["container_name"], script_log, docker_log)
+    script_log.info("==============================Executing test==============================")
 
-def remove_container(container_name):
+def remove_container(container_name, script_log, docker_log):
+    script_log.info("Removing container: %s...", container_name)
     try:
-        print(f"[INFO] Removing container: {container_name}")
-        subprocess.run(["docker", "rm", "-f", container_name], check=True)
+        run_command(["docker", "rm", "-f", container_name], docker_log)
+        script_log.info("Container removed: %s", container_name)
     except subprocess.CalledProcessError as e:
-        print(f"[WARNING] Failed to remove container {container_name}: {e}")
-
+        script_log.warning("Container removing failed: %s", container_name)
 
 
-
-def test_custom_dockerfile(dockerfile_path, cfg, use_cache=False):
+def test_custom_dockerfile(dockerfile_path, cfg, script_log, docker_log, sqlancer_log, run_dir, use_cache=False):
+    script_log.info("==============================Executing test==============================")
+    
     dbms=cfg["dbms"]
 
-    start_db_container(dbms, cfg)
+    start_db_container(dbms, cfg, script_log, docker_log)
     start_sqlancer_container(
         dbms=dbms,
         host_container_name=cfg["container_name"],
         username=cfg["username"],
         password=cfg["password"],
         oracle=cfg["oracle"],
         threads=cfg["num_threads"],
-        timeout=cfg["timeout_seconds"]
+        timeout=cfg["timeout_seconds"],
+        script_log=script_log,
+        sqlancer_log=sqlancer_log,
+        docker_log=docker_log,
+        run_dir=run_dir
     )
 
-    remove_container(cfg["container_name"])
-
+    remove_container(cfg["container_name"], script_log, docker_log)
+    script_log.info("==============================Executing test==============================")
 
diff --git a/utils.py b/utils.py
