Repository: exasol/integration-test-docker-environment (language: python)

Issue:
Add support of file logging for Luigi tasks 
## Background

The standard logging for Luigi is to log to console only. This is bad when we want to store logging for CI builds, or when customers need to share logs.

Luigi already accepts Python log configuration files. We need to create this file on the fly, and pass to luigi.build, ex. luigi.build([task], workers=5, local_scheduler=True, logging_conf_file="luigi.conf")

However, the log can be configured only once. All subsequent log configs will be ignored.

The original idea to log to a symlink (#205) is not feasible, the filehandle of the first configure-log invocation will point to the log-target, not to the symlink.

The new idea is to log to $OUTPUT/jobs/logs/main.log

## Acceptance Criteria
1. Create a log configuration file on the file for Luigi and pass to luigi.build()
2. Log target should be $OUTPUT/jobs/logs/main.log


Discussion / hints:

Fix patch:
diff --git a/doc/changes/changes_0.10.0.md b/doc/changes/changes_0.10.0.md
index 20f5f0b16..9d344b07b 100644
--- a/doc/changes/changes_0.10.0.md
+++ b/doc/changes/changes_0.10.0.md
@@ -25,6 +25,7 @@ If you need further versions, please open an issue.
 
  - #198: Added support for Docker db 7.1.7, 7.1.8 and 7.0.17 
  - #201: Added support for Docker db 7.1.9 and 7.0.18
+ - #207: Added support of file logging for Luigi tasks
 
 ## Refactoring:
 
diff --git a/setup.py b/setup.py
index bbb785c94..6e8ddc807 100644
--- a/setup.py
+++ b/setup.py
@@ -54,6 +54,7 @@
                                                 'docker_db_config/7.1.7/*',
                                                 'docker_db_config/7.1.8/*',
                                                 'docker_db_config/7.1.9/*',
+                                                'templates/*',
                                                 'test_container_config/*']}
 
 install_requires = \


Test patch:
diff --git a/exasol_integration_test_docker_environment/cli/common.py b/exasol_integration_test_docker_environment/cli/common.py
index fb4bbf4cf..4ac01b18d 100644
--- a/exasol_integration_test_docker_environment/cli/common.py
+++ b/exasol_integration_test_docker_environment/cli/common.py
@@ -4,7 +4,12 @@
 import traceback
 from datetime import datetime
 from pathlib import Path
-from typing import Callable, Tuple, Set
+from typing import (
+    Callable,
+    Tuple,
+    Set,
+    Optional
+)
 
 import luigi
 import networkx
@@ -12,6 +17,7 @@
 
 from exasol_integration_test_docker_environment.lib import extract_modulename_for_build_steps
 from exasol_integration_test_docker_environment.lib.base.dependency_logger_base_task import DependencyLoggerBaseTask
+from exasol_integration_test_docker_environment.lib.base.luigi_log_config import get_luigi_log_config, get_log_path
 from exasol_integration_test_docker_environment.lib.base.task_dependency import TaskDependency, DependencyState
 
 
@@ -78,23 +84,25 @@ def import_build_steps(flavor_path: Tuple[str, ...]):
         spec.loader.exec_module(module)
 
 
-def generate_root_task(task_class, *args, **kwargs):
+def generate_root_task(task_class, *args, **kwargs) -> DependencyLoggerBaseTask:
     strftime = datetime.now().strftime('%Y_%m_%d_%H_%M_%S')
     params = {"job_id": f"{strftime}_{task_class.__name__}"}
     params.update(kwargs)
     return task_class(**params)
 
 
-def run_task(task_creator: Callable[[], DependencyLoggerBaseTask],
-             workers: int,
-             task_dependencies_dot_file: str) \
+def run_task(task_creator: Callable[[], DependencyLoggerBaseTask], workers: int,
+             task_dependencies_dot_file: Optional[str]) \
         -> Tuple[bool, DependencyLoggerBaseTask]:
     setup_worker()
     start_time = datetime.now()
     task = task_creator()
     success = False
     try:
-        no_scheduling_errors = luigi.build([task], workers=workers, local_scheduler=True, log_level="INFO")
+        with get_luigi_log_config(get_log_path()) as luigi_config:
+            no_scheduling_errors = luigi.build([task], workers=workers,
+                                               local_scheduler=True,
+                                               logging_conf_file=f'{luigi_config}')
         success = not task.failed_target.exists() and no_scheduling_errors
         if success:
             handle_success(task, task_dependencies_dot_file, start_time)
@@ -110,7 +118,7 @@ def run_task(task_creator: Callable[[], DependencyLoggerBaseTask],
         task.cleanup(success)
 
 
-def handle_failure(task: DependencyLoggerBaseTask, task_dependencies_dot_file: str, start_time: datetime):
+def handle_failure(task: DependencyLoggerBaseTask, task_dependencies_dot_file: Optional[str], start_time: datetime):
     generate_graph_from_task_dependencies(task, task_dependencies_dot_file)
     timedelta = datetime.now() - start_time
     print("The command failed after %s s with:" % timedelta.total_seconds())
@@ -123,13 +131,13 @@ def print_task_failures(task: DependencyLoggerBaseTask):
         print(failure)
     print()
 
-def handle_success(task: DependencyLoggerBaseTask, task_dependencies_dot_file: str, start_time: datetime):
+def handle_success(task: DependencyLoggerBaseTask, task_dependencies_dot_file: Optional[str], start_time: datetime):
     generate_graph_from_task_dependencies(task, task_dependencies_dot_file)
     timedelta = datetime.now() - start_time
     print("The command took %s s" % timedelta.total_seconds())
 
 
-def generate_graph_from_task_dependencies(task: DependencyLoggerBaseTask, task_dependencies_dot_file: str):
+def generate_graph_from_task_dependencies(task: DependencyLoggerBaseTask, task_dependencies_dot_file: Optional[str]):
     if task_dependencies_dot_file is not None:
         print(f"Generate Task Dependency Graph to {task_dependencies_dot_file}")
         print()
diff --git a/exasol_integration_test_docker_environment/lib/__init__.py b/exasol_integration_test_docker_environment/lib/__init__.py
index ee3ca41af..1d11f433b 100644
--- a/exasol_integration_test_docker_environment/lib/__init__.py
+++ b/exasol_integration_test_docker_environment/lib/__init__.py
@@ -1,3 +1,5 @@
 
 def extract_modulename_for_build_steps(path: str):
     return path.replace("/", "_").replace(".", "_")
+
+PACKAGE_NAME = "exasol_integration_test_docker_environment"
diff --git a/exasol_integration_test_docker_environment/lib/base/base_task.py b/exasol_integration_test_docker_environment/lib/base/base_task.py
index 2e27e09a7..4bc4fc27f 100644
--- a/exasol_integration_test_docker_environment/lib/base/base_task.py
+++ b/exasol_integration_test_docker_environment/lib/base/base_task.py
@@ -359,3 +359,4 @@ def cleanup_child_task(self, success: bool, cleanup_checklist: Set[str]):
 
     def cleanup_task(self, success: bool):
         pass
+
diff --git a/exasol_integration_test_docker_environment/lib/base/luigi_log_config.py b/exasol_integration_test_docker_environment/lib/base/luigi_log_config.py
new file mode 100644
index 000000000..f3d046f40
--- /dev/null
+++ b/exasol_integration_test_docker_environment/lib/base/luigi_log_config.py
@@ -0,0 +1,64 @@
+import contextlib
+import os
+import tempfile
+from pathlib import Path
+from typing import Optional
+
+import jinja2
+import logging
+from exasol_integration_test_docker_environment.lib import PACKAGE_NAME
+from exasol_integration_test_docker_environment.lib.config.build_config import build_config
+
+global_log_file: Optional[Path] = None
+"""
+Global variable used to save log path. Should only be used within method validate_log_file(). 
+"""
+
+LOG_ENV_VARIABLE_NAME = "EXA_BUILD_LOG"
+
+
+def get_log_path() -> Path:
+    """
+    Retrieve the log-file path. Default path is $output_path/jobs/logs/main.log, but can be overwritten by
+    the environment variable LOG_ENV_VARIABLE_NAME.
+    """
+    main_log_path = Path(build_config().output_directory) / "jobs" / "logs"
+    main_log_path.mkdir(parents=True, exist_ok=True)
+    def_log_path = main_log_path / "main.log"
+    env_log_path = os.getenv(LOG_ENV_VARIABLE_NAME)
+    if env_log_path is not None:
+        log_path = Path(env_log_path)
+    else:
+        log_path = def_log_path
+    return log_path
+
+
+def validate_log_file(log_file: Path):
+    global global_log_file
+    # If build config is set multiple times, we must ensure the path of the log-file does not change
+    # The logging always will print to logfile in the first configured output directory (restriction by Luigi).
+    if global_log_file is not None and global_log_file.absolute() != log_file.absolute():
+        raise ValueError("Log file location for Luigi has been changed. "
+                         "This is not allowed to change between consecutive task invocations.")
+    global_log_file = log_file
+
+
+@contextlib.contextmanager
+def get_luigi_log_config(log_file_target: Path, console_log_level: int = logging.WARNING) -> Path:
+    """
+    Yields a context manager containing the path of the log-config file.
+    log_file_target contains the location of the log-file.
+    console_log_level indicates the log_level (@see https://docs.python.org/3/library/logging.html#logging-levels)
+    The log-level for the log-file is always logging.DEBUG!
+    """
+    validate_log_file(log_file_target)
+    env = jinja2.Environment(loader=jinja2.PackageLoader(PACKAGE_NAME),
+                             autoescape=jinja2.select_autoescape())
+    template = env.get_template("luigi_log.conf")
+    rendered_template = template.render(console_log_level=logging.getLevelName(console_log_level),
+                                        log_file_target=str(log_file_target))
+    with tempfile.TemporaryDirectory() as temp_dir:
+        temp_luigi_conf_path = Path(temp_dir) / "luigi_log.conf"
+        with open(temp_luigi_conf_path, "w") as f:
+            f.write(rendered_template)
+        yield temp_luigi_conf_path
diff --git a/exasol_integration_test_docker_environment/lib/config/build_config.py b/exasol_integration_test_docker_environment/lib/config/build_config.py
index daf5cad3c..879c5b477 100644
--- a/exasol_integration_test_docker_environment/lib/config/build_config.py
+++ b/exasol_integration_test_docker_environment/lib/config/build_config.py
@@ -1,5 +1,6 @@
 import luigi
 
+DEFAULT_OUTPUT_DIRECTORY = ".build_output"
 
 class build_config(luigi.Config):
     force_pull = luigi.BoolParameter(False)
@@ -9,6 +10,6 @@ class build_config(luigi.Config):
     log_build_context_content = luigi.BoolParameter(False)
     # keep_build_context = luigi.BoolParameter(False)
     temporary_base_directory = luigi.OptionalParameter(None)
-    output_directory = luigi.Parameter(".build_output")
+    output_directory = luigi.Parameter(DEFAULT_OUTPUT_DIRECTORY)
     cache_directory = luigi.OptionalParameter("")
     build_name = luigi.OptionalParameter("")
diff --git a/exasol_integration_test_docker_environment/lib/test_environment/create_ssl_certificates_task.py b/exasol_integration_test_docker_environment/lib/test_environment/create_ssl_certificates_task.py
index e105996c2..5918a5562 100644
--- a/exasol_integration_test_docker_environment/lib/test_environment/create_ssl_certificates_task.py
+++ b/exasol_integration_test_docker_environment/lib/test_environment/create_ssl_certificates_task.py
@@ -3,6 +3,7 @@
 import pkg_resources
 from jinja2 import Template
 
+from exasol_integration_test_docker_environment.lib import PACKAGE_NAME
 from exasol_integration_test_docker_environment.lib.base.docker_base_task import DockerBaseTask
 from exasol_integration_test_docker_environment.lib.data.docker_volume_info import DockerVolumeInfo
 from exasol_integration_test_docker_environment.lib.test_environment.analyze_test_container import \
@@ -87,7 +88,7 @@ def _construct_complete_host_name(self):
     def create_certificate(self) -> None:
         script_name = "create_certificates.sh"
         template_str = pkg_resources.resource_string(
-            "exasol_integration_test_docker_environment",
+            PACKAGE_NAME,
             f"test_container_config/{script_name}")  # type: bytes
         template = Template(template_str.decode("utf-8"))
         rendered_template = template.render(HOST_NAME=self._construct_complete_host_name,
diff --git a/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_container.py b/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_container.py
index 05147d6d9..78d8ca182 100644
--- a/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_container.py
+++ b/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_container.py
@@ -7,6 +7,7 @@
 from docker.models.containers import Container
 from docker.transport import unixconn
 
+from exasol_integration_test_docker_environment.lib import PACKAGE_NAME
 from exasol_integration_test_docker_environment.lib.base.docker_base_task import DockerBaseTask
 from exasol_integration_test_docker_environment.lib.base.json_pickle_parameter import JsonPickleParameter
 from exasol_integration_test_docker_environment.lib.data.container_info import ContainerInfo
@@ -187,7 +188,7 @@ def register_certificates(self, test_container: Container):
         if self.certificate_volume_name is not None:
             script_name = "install_root_certificate.sh"
             script_str = pkg_resources.resource_string(
-                "exasol_integration_test_docker_environment",
+                PACKAGE_NAME,
                 f"test_container_config/{script_name}")  # type: bytes
 
             script_location_in_container = f"scripts/{script_name}"
diff --git a/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_database.py b/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_database.py
index 660a790c0..4a49cbc9d 100644
--- a/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_database.py
+++ b/exasol_integration_test_docker_environment/lib/test_environment/spawn_test_database.py
@@ -10,6 +10,7 @@
 from docker.models.volumes import Volume
 from jinja2 import Template
 
+from exasol_integration_test_docker_environment.lib import PACKAGE_NAME
 from exasol_integration_test_docker_environment.lib.base.docker_base_task import DockerBaseTask
 from exasol_integration_test_docker_environment.lib.base.json_pickle_parameter import JsonPickleParameter
 from exasol_integration_test_docker_environment.lib.base.still_running_logger import StillRunningLogger
@@ -220,7 +221,7 @@ def _upload_init_db_files(self,
                               db_private_network: str):
         copy = DockerContainerCopy(volume_preperation_container)
         init_db_script_str = pkg_resources.resource_string(
-            "exasol_integration_test_docker_environment",
+            PACKAGE_NAME,
             f"{self.docker_db_config_resource_name}/init_db.sh") # type: bytes
 
         copy.add_string_to_file("init_db.sh", init_db_script_str.decode("utf-8"))
@@ -232,7 +233,7 @@ def _add_exa_conf(self, copy: DockerContainerCopy,
         certificate_dir = CERTIFICATES_MOUNT_DIR if self.certificate_volume_name is not None \
                             else CERTIFICATES_DEFAULT_DIR
         template_str = pkg_resources.resource_string(
-            "exasol_integration_test_docker_environment",
+            PACKAGE_NAME,
             f"{self.docker_db_config_resource_name}/EXAConf") # type: bytes
         template = Template(template_str.decode("utf-8"))
         rendered_template = template.render(private_network=db_private_network,
diff --git a/exasol_integration_test_docker_environment/templates/luigi_log.conf b/exasol_integration_test_docker_environment/templates/luigi_log.conf
new file mode 100644
index 000000000..fb3307ba0
--- /dev/null
+++ b/exasol_integration_test_docker_environment/templates/luigi_log.conf
@@ -0,0 +1,38 @@
+[loggers]
+keys=root,luigi
+
+[handlers]
+keys=consoleHandler,fileHandler
+
+[formatters]
+keys=fileFormatter,consoleFormatter
+
+[logger_root]
+level=DEBUG
+handlers=consoleHandler,fileHandler
+
+[logger_luigi]
+level=DEBUG
+handlers=consoleHandler,fileHandler
+qualname=luigi-interface
+propagate=0
+
+[handler_consoleHandler]
+class=StreamHandler
+level={{console_log_level}}
+formatter=consoleFormatter
+args=(sys.stdout,)
+
+[handler_fileHandler]
+class=FileHandler
+level=DEBUG
+formatter=fileFormatter
+args=('{{log_file_target}}',)
+
+[formatter_fileFormatter]
+format=%(asctime)s - %(name)s - %(levelname)s - %(message)s
+datefmt=
+
+[formatter_consoleFormatter]
+format=%(levelname)s - %(message)s
+datefmt=
diff --git a/exasol_integration_test_docker_environment/test/test_common_run_task.py b/exasol_integration_test_docker_environment/test/test_common_run_task.py
new file mode 100644
index 000000000..427abe138
--- /dev/null
+++ b/exasol_integration_test_docker_environment/test/test_common_run_task.py
@@ -0,0 +1,31 @@
+import subprocess
+import unittest
+from pathlib import Path
+
+
+class CommonRunTaskTest(unittest.TestCase):
+    """
+    All tests are executed in another process as we test the logging behavior which can be configured
+    only once for a process!
+    Note that multiprocessing.Process() does not work as it forks the current process, and thus inherits the
+    logging configuration. Hence we need to start a new process with subprocess.
+    """
+
+    def _execute_in_new_process(self, target):
+        path = Path(__file__)
+        args = ("python", f"{path.parent.absolute()}/test_common_run_task_subprocess.py", target)
+        p = subprocess.run(args)
+        p.check_returncode()
+
+    def test_same_logging_file(self):
+        self._execute_in_new_process(target="run_test_same_logging_file")
+
+    def test_same_logging_file_custom_log_location(self):
+        self._execute_in_new_process(target="run_test_same_logging_file_env_log_path")
+
+    def test_different_logging_file_raises_error(self):
+        self._execute_in_new_process(target="run_test_different_logging_file_raises_error")
+
+
+if __name__ == '__main__':
+    unittest.main()
diff --git a/exasol_integration_test_docker_environment/test/test_common_run_task_subprocess.py b/exasol_integration_test_docker_environment/test/test_common_run_task_subprocess.py
new file mode 100644
index 000000000..9e54042c5
--- /dev/null
+++ b/exasol_integration_test_docker_environment/test/test_common_run_task_subprocess.py
@@ -0,0 +1,91 @@
+import os
+import sys
+import tempfile
+from pathlib import Path
+
+import luigi
+
+from exasol_integration_test_docker_environment.cli.common import generate_root_task, run_task
+from exasol_integration_test_docker_environment.lib.base.dependency_logger_base_task import DependencyLoggerBaseTask
+
+from exasol_integration_test_docker_environment.lib.base.luigi_log_config import LOG_ENV_VARIABLE_NAME
+
+
+class TestTask(DependencyLoggerBaseTask):
+    x = luigi.Parameter()
+
+    def run(self):
+        self.logger.info(f"Logging: {self.x}")
+
+
+def run_simple_tasks(log_path: Path) -> None:
+    NUMBER_TASK = 5
+    task_id_generator = (x for x in range(NUMBER_TASK))
+
+    def create_task():
+        return generate_root_task(task_class=TestTask, x=f"{next(task_id_generator)}")
+
+    for i in range(NUMBER_TASK):
+        success, task = run_task(create_task, workers=5, task_dependencies_dot_file=None)
+        assert success
+
+    assert log_path.exists()
+    with open(log_path, "r") as f:
+        log_content = f.read()
+        for i in range(NUMBER_TASK):
+            assert f"Logging: {i}" in log_content
+
+
+def run_test_same_logging_file() -> None:
+    """
+    Integration test which verifies that re-using the same logging for multiple tasks works as expected,
+    using the default log path
+    """
+    with tempfile.TemporaryDirectory() as temp_dir:
+        os.chdir(temp_dir)
+        log_path = Path(temp_dir) / ".build_output" / "jobs" / "logs" / "main.log"
+        run_simple_tasks(log_path=log_path)
+
+
+def run_test_same_logging_file_env_log_path() -> None:
+    """
+    Integration test which verifies that re-using the same logging for multiple tasks works as expected,
+    using a custom log path
+    """
+
+    with tempfile.TemporaryDirectory() as temp_dir:
+        log_path = Path(temp_dir) / "main.log"
+        os.environ[LOG_ENV_VARIABLE_NAME] = str(log_path)
+        run_simple_tasks(log_path=log_path)
+
+
+def run_test_different_logging_file_raises_error() -> None:
+    """
+    Integration test which verifies that changing the log path from one invocation of run_task to the next will raise
+    an error.
+    """
+
+    with tempfile.TemporaryDirectory() as temp_dir:
+        task_creator = lambda: generate_root_task(task_class=TestTask, x="Test")
+
+        success, task = run_task(task_creator, workers=5, task_dependencies_dot_file=None)
+        assert success
+        log_path = Path(temp_dir) / "main.log"
+        os.environ[LOG_ENV_VARIABLE_NAME] = str(log_path)
+        success, task = run_task(task_creator, workers=5, task_dependencies_dot_file=None)
+        assert success is False
+
+
+if __name__ == '__main__':
+    test_type = sys.argv[1]
+
+    dispatcher = {
+        "run_test_different_logging_file_raises_error": run_test_different_logging_file_raises_error,
+        "run_test_same_logging_file_env_log_path": run_test_same_logging_file_env_log_path,
+        "run_test_same_logging_file": run_test_same_logging_file,
+    }
+    try:
+        dispatcher[test_type]()
+    except KeyError as e:
+        raise ValueError("Unknow Test argument") from e
+
diff --git a/exasol_integration_test_docker_environment/test/test_docker_build_base.py b/exasol_integration_test_docker_environment/test/test_docker_build_base.py
index 71ac0a885..5d9536c61 100644
--- a/exasol_integration_test_docker_environment/test/test_docker_build_base.py
+++ b/exasol_integration_test_docker_environment/test/test_docker_build_base.py
@@ -2,7 +2,6 @@
 import unittest
 from pathlib import Path
 
-import docker
 import luigi
 from luigi import Parameter