feat: logs hostname and execution time TDE-431 (#77)

* feat: log argo node id (pod_name) and execution time

* feat: upgrade linz_logger and add default 'hostname' key for logging

* chore: move the pylint disabler for duplicate code

* feat: add a SIMILARITIES section in pylint config

* feat: upgrade linz-logger to v0.9.0 with hostname as default key.

* refactor: reduce 'min-similarity-lines' from 10 to 4 since the duplicated code has been sorted

.pylintrc

@@ -9,3 +9,8 @@ disable =
 max-line-length=127
 [MISCELLANEOUS]
 notes=XXX
+[SIMILARITIES]
+min-similarity-lines=4
+ignore-comments=yes
+ignore-docstrings=yes
+ignore-imports=yes

pyproject.toml

@@ -38,7 +38,7 @@ authors = [
 [tool.poetry.dependencies]
 python = "^3.8.10"
 boto3 = "^1.24.12"
-linz-logger = "^0.6.0"
+linz-logger = "^0.9.0"
 
 [tool.poetry.dev-dependencies]
 black = "^22.3.0"

scripts/create_polygons.py

@@ -11,6 +11,7 @@
 
 # osgeo is embbed in the Docker image
 from osgeo import gdal  # pylint: disable=import-error
+from time_helper import time_in_ms
 
 
 def create_mask(file_path: str, mask_dst: str) -> None:
@@ -40,6 +41,7 @@ def get_pixel_count(file_path: str) -> int:
 
 
 def main() -> None:
+    start_time = time_in_ms()
     source = parse_source()
     output_files = []
 
@@ -85,6 +87,8 @@ def main() -> None:
     with open("/tmp/file_list.json", "w", encoding="utf-8") as jf:
         json.dump(output_files, jf)
 
+    get_log().info("create_polygons_end", source=source, duration=time_in_ms() - start_time)
+
 
 if __name__ == "__main__":
     main()

scripts/gdal_helper.py

@@ -4,6 +4,7 @@
 
 from aws_helper import get_bucket_name_from_path, get_credentials, is_s3
 from linz_logger import get_log
+from time_helper import time_in_ms
 
 
 class GDALExecutionException(Exception):
@@ -67,12 +68,15 @@ def run_gdal(
     if output_file:
         command.append(output_file)
 
+    start_time = time_in_ms()
     try:
-        get_log().debug("run_gdal", command=command_to_string(command))
+        get_log().debug("run_gdal_start", command=command_to_string(command))
         proc = subprocess.run(command, env=gdal_env, stdout=subprocess.PIPE, stderr=subprocess.PIPE, check=True)
     except subprocess.CalledProcessError as cpe:
         get_log().error("run_gdal_failed", command=command_to_string(command), error=str(cpe.stderr, "utf-8"))
         raise GDALExecutionException(f"GDAL {str(cpe.stderr, 'utf-8')}") from cpe
+    finally:
+        get_log().info("run_gdal_end", command=command_to_string(command), duration=time_in_ms() - start_time)
 
     if proc.stderr:
         get_log().error("run_gdal_error", command=command_to_string(command), error=proc.stderr.decode())

scripts/non_visual_qa.py

@@ -5,6 +5,7 @@
 from file_helper import is_tiff
 from gdal_helper import GDALExecutionException, run_gdal
 from linz_logger import get_log
+from time_helper import time_in_ms
 
 
 class FileCheck:
@@ -121,8 +122,11 @@ def run(self) -> None:
 
 
 def main() -> None:
+    start_time = time_in_ms()
     source = parse_source()
 
+    get_log().info("non_visual_qa_start", source=source)
+
     # Get srs
     gdalsrsinfo_command = ["gdalsrsinfo", "-o", "wkt", "EPSG:2193"]
     gdalsrsinfo_result = run_gdal(gdalsrsinfo_command)
@@ -144,6 +148,8 @@ def main() -> None:
         else:
             get_log().info("non_visual_qa_passed", file=file_check.path)
 
+    get_log().info("non_visual_qa_end", source=source, duration=time_in_ms() - start_time)
+
 
 if __name__ == "__main__":
     main()

scripts/standardising.py

@@ -5,10 +5,14 @@
 from file_helper import get_file_name_from_path, is_tiff
 from gdal_helper import run_gdal
 from linz_logger import get_log
+from time_helper import time_in_ms
+
+start_time = time_in_ms()
 
 source = parse_source()
 
-get_log().info("standardising", source=source)
+get_log().info("standardising_start", source=source)
+
 gdal_env = os.environ.copy()
 
 for file in source:
@@ -59,3 +63,5 @@
         "sparse_ok=true",
     ]
     run_gdal(command, input_file=file, output_file=tmp_file_path)
+
+    get_log().info("standardising_end", source=source, duration=time_in_ms() - start_time)

scripts/time_helper.py

@@ -0,0 +1,5 @@
+import time
+
+
+def time_in_ms() -> float:
+    return time.time() * 1000