#63 improved logging of ansible tasks (#64)

#63 improved logging of ansible tasks

Display duration of Ansible tasks.
Display Ansible messages and error for failing fixtures in ci build.
Installed rsync to enable replacing up ansible copy by faster synchronize.

.github/workflows/check_ci.yaml

@@ -19,8 +19,7 @@ jobs:
 
      - name: Run pytest
        run: >
-         poetry run pytest
-         -o log_cli=true
+         poetry run pytest -o log_cli=true -o log_cli_level=INFO
          test/unit
          test/integration/test_create_dss_docker_image.py
        env: # Set the secret as an env variable

doc/changes/changes_0.1.0.md

@@ -24,11 +24,13 @@ Version: 0.1.0
 ## Bug Fixes
 
 * #1: Fixed CI build
+* #61: Change initial password of Jupyter notebooks to "dss"
 
 ## Refactoring
 
 * #5: Renamed all occurrences of "script language developer" by "data science"
 * #56: Moved jupyter notebook files again
+* #63: Improved logging of Ansible tasks
 
 ## Documentation
 

exasol/ds/sandbox/lib/ansible/ansible_access.py

@@ -1,7 +1,9 @@
 import ansible_runner
+import json
 import logging
 
-from typing import Callable
+from dataclasses import dataclass
+from typing import Callable, Dict, Optional
 
 from exasol.ds.sandbox.lib.ansible.ansible_run_context import AnsibleRunContext
 from exasol.ds.sandbox.lib.logging import get_status_logger, LogType
@@ -11,19 +13,30 @@ class AnsibleException(RuntimeError):
     pass
 
 
+AnsibleEvent = Dict[str, any]
+
+
 class AnsibleAccess:
     """
     Provides access to ansible runner.
     @raises: AnsibleException if ansible execution fails
     """
     @staticmethod
-    def run(private_data_dir: str, run_ctx: AnsibleRunContext, printer: Callable[[str], None]):
+    def run(
+            private_data_dir: str,
+            run_ctx: AnsibleRunContext,
+            event_logger: Callable[[str], None],
+            event_handler: Callable[[AnsibleEvent], bool] = None,
+    ):
         quiet = not get_status_logger(LogType.ANSIBLE).isEnabledFor(logging.INFO)
-        r = ansible_runner.run(private_data_dir=private_data_dir,
-                               playbook=run_ctx.playbook,
-                               quiet=quiet,
-                               extravars=run_ctx.extra_vars)
+        r = ansible_runner.run(
+            private_data_dir=private_data_dir,
+            playbook=run_ctx.playbook,
+            quiet=quiet,
+            event_handler=event_handler,
+            extravars=run_ctx.extra_vars,
+        )
         for e in r.events:
-            printer(e)
+            event_logger(json.dumps(e, indent=2))
         if r.rc != 0:
             raise AnsibleException(r.rc)

exasol/ds/sandbox/lib/ansible/ansible_runner.py

@@ -1,7 +1,9 @@
+import logging
+
 from pathlib import Path
 from typing import Tuple
 
-from exasol.ds.sandbox.lib.ansible.ansible_access import AnsibleAccess
+from exasol.ds.sandbox.lib.ansible.ansible_access import AnsibleAccess, AnsibleEvent
 from exasol.ds.sandbox.lib.ansible.ansible_run_context import AnsibleRunContext
 from exasol.ds.sandbox.lib.logging import get_status_logger, LogType
 from exasol.ds.sandbox.lib.setup_ec2.host_info import HostInfo
@@ -17,13 +19,36 @@ class AnsibleRunner:
     def __init__(self, ansible_access: AnsibleAccess, work_dir: Path):
         self._ansible_access = ansible_access
         self._work_dir = work_dir
+        self._duration_logger = AnsibleRunner.duration_logger()
+
+    @classmethod
+    def duration_logger(cls) -> logging.Logger:
+        def handler():
+            handler = logging.StreamHandler()
+            handler.setFormatter(logging.Formatter('%(message)s'))
+            return handler
+        logger = logging.getLogger(f"{__name__}:{cls.__name__}")
+        logger.setLevel(logging.DEBUG)
+        logger.propagate = False
+        logger.addHandler(handler())
+        return logger
 
-    @staticmethod
-    def printer(msg: str):
-        LOG.debug(msg)
+    def event_handler(self, event: AnsibleEvent) -> bool:
+        if not "event_data" in event:
+            return True
+        duration = event["event_data"].get("duration", 0)
+        if duration > 0.5:
+            self._duration_logger.debug(f"duration: {round(duration)} seconds")
+        return True
 
     def run(self, ansible_run_context: AnsibleRunContext, host_infos: Tuple[HostInfo]):
         inventory_content = render_template("inventory.jinja", host_infos=host_infos)
         with open(self._work_dir / "inventory", "w") as f:
             f.write(inventory_content)
-        self._ansible_access.run(str(self._work_dir), ansible_run_context, self.printer)
+        event_handler = self.event_handler if LOG.isEnabledFor(logging.INFO) else None
+        self._ansible_access.run(
+            str(self._work_dir),
+            ansible_run_context,
+            event_logger=LOG.debug,
+            event_handler=self.event_handler,
+        )

exasol/ds/sandbox/runtime/ansible/general_setup_tasks.yml

@@ -3,6 +3,9 @@
     upgrade: yes
     update_cache: yes
   become: "{{need_sudo}}"
+- name: Install rsync
+  include_role:
+    name: rsync
 - name: Install Poetry
   include_role:
     name: poetry

exasol/ds/sandbox/runtime/ansible/roles/jupyter/defaults/main.yml

@@ -5,8 +5,9 @@ jupyterlab:
   ip: '*'
   config: "{{user_home}}/.jupyter/jupyter_lab_config.py"
   virtualenv: "{{user_home}}/jupyterenv"
-  password: "{{ lookup('ansible.builtin.env', 'JUPYTER_LAB_PASSWORD', default='script-languages') }}"
+  password: "{{ lookup('ansible.builtin.env', 'JUPYTER_LAB_PASSWORD', default='dss') }}"
   notebook_folder: "{{user_home}}/notebooks"
 
 apt_dependencies:
+  - rsync=3.1.3-8ubuntu0.7
   - virtualenv=20.0.17-1ubuntu0.4

exasol/ds/sandbox/runtime/ansible/roles/jupyter/tasks/tutorial.yml

@@ -1,6 +1,7 @@
 ---
 - name: Copy notebook content
-  ansible.builtin.copy:
+  ansible.builtin.synchronize:
     src: "notebook/"
     dest: "{{jupyterlab.notebook_folder}}"
-    mode: 0644
+    rsync_opts:
+      - "--chmod=0644"

exasol/ds/sandbox/runtime/ansible/roles/rsync/defaults/main.yml

@@ -0,0 +1,4 @@
+---
+
+apt_dependencies:
+  - rsync=3.1.3-8ubuntu0.7

exasol/ds/sandbox/runtime/ansible/roles/rsync/tasks/main.yml

@@ -0,0 +1,6 @@
+- name: Install rsync
+  apt:
+    name: "{{apt_dependencies}}"
+    state: latest
+    update_cache: true
+  become: "{{need_sudo}}"

test/integration/test_create_dss_docker_image.py

@@ -1,7 +1,9 @@
 import docker
+import io
 import pytest
 import re
 import requests
+import sys
 import tenacity
 import time
 import typing

test/unit/test_ansible.py

@@ -8,6 +8,7 @@
     AnsibleResourceRepository
 from exasol.ds.sandbox.lib.ansible.ansible_run_context import AnsibleRunContext, \
     default_ansible_run_context
+from exasol.ds.sandbox.lib.ansible.ansible_access import AnsibleEvent
 from exasol.ds.sandbox.lib.setup_ec2.host_info import HostInfo
 from exasol.ds.sandbox.lib.setup_ec2.run_install_dependencies import run_install_dependencies
 
@@ -22,8 +23,12 @@ def __init__(self, delegate: Optional[Callable[[str, AnsibleRunContext], None]]
         self.arguments = namedtuple("Arguments", "private_data_dir run_ctx")
         self.delegate = delegate
 
-    def run(self, private_data_dir: str, run_ctx: AnsibleRunContext, printer: Callable[[str], None]):
-
+    def run(self,
+            private_data_dir: str,
+            run_ctx: AnsibleRunContext,
+            event_handler: Callable[[AnsibleEvent], bool],
+            event_logger: Callable[[str], None],
+            ):
         self.call_arguments = self.arguments(private_data_dir, run_ctx)
         if self.delegate is not None:
             self.delegate(private_data_dir, run_ctx)