Merge branch 'release/2.7.1-alpha.4'

project-docs/release-notes/version-2.7.1.md

@@ -6,6 +6,9 @@ Features Changed
 
 * Updated VS Code to version 1.89.1.
 
+* Reduction of noise in logging for session manager, secrets manager and
+  training portal, with additional more specific logging on what each is doing.
+
 Bugs Fixed
 ----------
 
@@ -64,11 +67,33 @@ Bugs Fixed
   objects associated with the workshop session would not be created. From the
   perspective of a workshop user the session would still appear to work as the
   workshop dashboard would still be accessible, but request objects would be
-  missing. Timeout for workshop session registration has been increased to 90
-  seconds.
+  missing. Timeout for workshop session registration has been increased to 45
+  seconds. Because default overall startup timeout is 60 seconds, cannot really
+  increase this much further. Will continue to monitor the situation and see
+  if other changes are needed, including increasing startup timeout to 90
+  seconds and timeout for workshop session registration with the operator to
+  60 seconds.
 
 * If text followed a clickable action and the `cascade` option was used, the
   subsequent clickable action would not be automatically triggered. It would
   work okay if the next clickable action immediately followed the first. This
   was broken when the cascade mechanim was extended to all clickable actions and
   not just examiner clickable actions.
+
+* When using `SecretExporter` and `SecretImporter` together, if the source
+  secret did not exist at the time these resources were created, then it would
+  take up to sixty seconds after the source secret was created before it was
+  copied to the target namespace, rather than being copied immediately.
+
+* When using `request.objects` and the Kubernetes resource failed client side
+  validation even before attempt to create it on the server, the error was not
+  being caught properly. Details of the error were still captured in the
+  session manager logs, but the details of what failed were not captured in
+  the status message of the `WorkshopAllocation` resource, nor was the status
+  of the resource updated to "Failed".
+
+* The pod security polices (obsolete Kubernetes versions) and security context
+  constraints (OpenShift) resources created for a workshop environment were
+  not being set as being owned by the workshop namespace. This meant these
+  resources were not being deleted automatically when the workshop environment
+  and workshop namespace were deleted.

secrets-manager/handlers/helpers.py

@@ -1,25 +1,6 @@
 import threading
 
 
-class global_logger:
-
-    local = threading.local()
-
-    def __init__(self, logger):
-        self.logger = logger
-
-    def __enter__(self):
-        self.previous = getattr(global_logger.local, "current", None)
-        global_logger.local.current = self.logger
-
-    def __exit__(self, *args):
-        global_logger.local.current = self.previous
-
-
-def get_logger():
-    return global_logger.local.current
-
-
 def lookup(obj, key, default=None):
     """Looks up a property within an object using a dotted path as key.
     If the property isn't found, then return the default value.

secrets-manager/handlers/namespace.py

@@ -1,14 +1,16 @@
+import logging
 import itertools
 
 import kopf
 
-from .helpers import global_logger
 
 from .secretcopier_funcs import reconcile_namespace as copier_reconcile_namespace
 
+logger = logging.getLogger("educates")
+
 
 @kopf.on.event("", "v1", "namespaces")
-def namespace_event(type, event, logger, secretcopier_index, secretexporter_index, **_):
+def namespace_event(type, event, secretcopier_index, secretexporter_index, **_):
     resource = event["object"]
     name = resource["metadata"]["name"]
 
@@ -26,5 +28,6 @@ def namespace_event(type, event, logger, secretcopier_index, secretexporter_inde
         )
     ]
 
-    with global_logger(logger):
-        copier_reconcile_namespace(name, resource, configs)
+    logger.debug(f"Triggering secretcopier reconcilation for namespace {name}.")
+
+    copier_reconcile_namespace(name, resource, configs)

secrets-manager/handlers/secret.py

@@ -1,22 +1,17 @@
+import logging
 import itertools
 
 import kopf
 
-from .helpers import global_logger
-
 from .secretcopier_funcs import reconcile_secret as copier_reconcile_secret
 from .secretinjector_funcs import reconcile_secret as injector_reconcile_secret
 
+logger = logging.getLogger("educates")
+
 
 @kopf.on.event("", "v1", "secrets")
 def secret_event(
-    type,
-    event,
-    logger,
-    secretcopier_index,
-    secretexporter_index,
-    secretinjector_index,
-    **_
+    type, event, secretcopier_index, secretexporter_index, secretinjector_index, **_
 ):
     obj = event["object"]
     namespace = obj["metadata"]["namespace"]
@@ -38,6 +33,14 @@ def secret_event(
 
     injector_configs = [value for value, *_ in secretinjector_index.values()]
 
-    with global_logger(logger):
-        copier_reconcile_secret(name, namespace, obj, copier_configs)
-        injector_reconcile_secret(name, namespace, obj, injector_configs)
+    logger.debug(
+        f"Triggering secretcopier reconcilation for secret {name} in namespace {namespace}."
+    )
+
+    copier_reconcile_secret(name, namespace, obj, copier_configs)
+
+    logger.debug(
+        f"Triggering secretinjector reconcilation for secret {name} in namespace {namespace}."
+    )
+
+    injector_reconcile_secret(name, namespace, obj, injector_configs)

secrets-manager/handlers/secretcopier.py

@@ -1,28 +1,65 @@
-import kopf
+import logging
 
-from .helpers import global_logger
+import kopf
 
 from .secretcopier_funcs import reconcile_config
 
 from .operator_config import OPERATOR_API_GROUP
 
+logger = logging.getLogger("educates")
+
 
 @kopf.index(f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers")
-def secretcopier_index(name, body, **_):
+def secretcopier_index(name, meta, body, **_):
+    generation = meta["generation"]
+
+    logger.debug("Add secretcopier %s with generation %s to cache.", name, generation)
+
     return {(None, name): body}
 
 
-@kopf.on.create(f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers")
 @kopf.on.resume(f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers")
+def secretcopier_reconcile_resume(name, meta, body, **_):
+    generation = meta["generation"]
+
+    logger.info("Secretcopier %s exists with generation %s.", name, generation)
+
+    reconcile_config(name, body)
+
+
+@kopf.on.create(f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers")
 @kopf.on.update(f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers")
-@kopf.timer(f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers", interval=60.0)
-def secretcopier_reconcile(name, body, logger, **_):
-    with global_logger(logger):
-        reconcile_config(name, body)
+def secretcopier_reconcile_update(name, meta, body, reason, **_):
+    generation = meta["generation"]
+
+    logger.info(
+        "Secretcopier %s %sd with generation %s.", name, reason.lower(), generation
+    )
+
+    reconcile_config(name, body)
+
+
+@kopf.timer(
+    f"secrets.{OPERATOR_API_GROUP}",
+    "v1beta1",
+    "secretcopiers",
+    initial_delay=30.0,
+    interval=60.0,
+)
+def secretcopier_reconcile_timer(name, meta, body, **_):
+    generation = meta["generation"]
+
+    logger.debug("Reconcile secretcopier %s with generation %s.", name, generation)
+
+    reconcile_config(name, body)
 
 
 @kopf.on.delete(
     f"secrets.{OPERATOR_API_GROUP}", "v1beta1", "secretcopiers", optional=True
 )
-def secretcopier_delete(name, body, logger, **_):
-    pass
+def secretcopier_delete(name, meta, **_):
+    generation = meta["generation"]
+
+    logger.info(
+        "Secretcopier %s with generation %s deleted.", name, generation
+    )

secrets-manager/handlers/secretcopier_funcs.py

@@ -1,12 +1,15 @@
 import copy
 import fnmatch
+import logging
 
 import pykube
 
-from .helpers import get_logger, lookup
+from .helpers import lookup
 
 from .operator_config import OPERATOR_API_GROUP
 
+logger = logging.getLogger("educates")
+
 
 def matches_target_namespace(namespace_name, namespace_obj, configs):
     """Returns all rules which match the namespace passed as argument."""
@@ -54,7 +57,7 @@ def bound_rule(rule, index):
 
             return rule_snapshot
 
-        for index, rule in enumerate(rules):
+        for index, rule in enumerate(rules, start=1):
             # Note that as soon as one selector fails where a condition was
             # stipulated, further checks are not done and the namespace is
             # ignored. In other words all conditions much match if more than one
@@ -255,7 +258,7 @@ def update_secret(namespace_name, rule):
     owner_source = lookup(rule, "ownerSource")
     rule_number = lookup(rule, "ruleNumber")
 
-    get_logger().info(
+    logger.debug(
         f"Processing rule {rule_number} from {owner_source} against namespace {namespace_name}."
     )
 
@@ -279,8 +282,12 @@ def update_secret(namespace_name, rule):
             api, namespace=source_secret_namespace
         ).get(name=source_secret_name)
 
-    except pykube.exceptions.KubernetesError as e:
-        get_logger().warning(
+    except pykube.exceptions.ObjectDoesNotExist:
+        logger.debug(f"Secret {source_secret_name} in namespace {source_secret_namespace} does not exist, skipping.")
+        return
+
+    except pykube.exceptions.KubernetesError:
+        logger.exception(
             f"Secret {source_secret_name} in namespace {source_secret_namespace} cannot be read."
         )
         return
@@ -308,7 +315,7 @@ def update_secret(namespace_name, rule):
         pass
 
     except pykube.exceptions.PyKubeError:
-        get_logger().warning(
+        logger.exception(
             f"SecretImporter {target_secret_name} in namespace {target_secret_namespace} cannot be read."
         )
         return
@@ -325,7 +332,7 @@ def update_secret(namespace_name, rule):
             .get("sharedSecret")
             != shared_secret
         ):
-            get_logger().warning(
+            logger.warning(
                 f"SecretImporter {target_secret_name} in namespace {target_secret_namespace} doesn't match."
             )
             return
@@ -437,19 +444,19 @@ def glob_match_name(name, items):
 
         except pykube.exceptions.HTTPError as e:
             if e.code == 409:
-                get_logger().warning(
+                logger.warning(
                     f"Secret {target_secret_name} in namespace {target_secret_namespace} already exists."
                 )
                 return
-            
-            get_logger().exception(
+
+            logger.exception(
                 f"Failed to copy secret {source_secret_name} from namespace {source_secret_namespace} to target namespace {target_secret_namespace} as {target_secret_name}."
             )
 
             return
 
-        get_logger().info(
-            f"Copied secret {source_secret_name} from namespace {source_secret_namespace} to target namespace {target_secret_namespace} as {target_secret_name}."
+        logger.info(
+            f"Copied secret {source_secret_name} from namespace {source_secret_namespace} to target namespace {target_secret_namespace} as {target_secret_name}, according to rule {rule_number} from {owner_source}."
         )
 
         return
@@ -476,7 +483,7 @@ def glob_match_name(name, items):
         and target_secret_owner_secret
         != f"{source_secret_namespace}/{source_secret_name}"
     ):
-        get_logger().warning(
+        logger.warning(
             f"Secret {target_secret_name} in namespace {target_secret_namespace} subject of multiple rules, {target_secret_owner_source} and {owner_source}, ignoring."
         )
         return
@@ -490,7 +497,8 @@ def glob_match_name(name, items):
 
     if (
         source_secret_item.obj["type"] == target_secret_item.obj["type"]
-        and source_secret_item.obj.get("data", {}) == target_secret_item.obj.get("data", {})
+        and source_secret_item.obj.get("data", {})
+        == target_secret_item.obj.get("data", {})
         and source_secret_labels == target_secret_labels
     ):
         return
@@ -509,8 +517,8 @@ def glob_match_name(name, items):
 
     target_secret_item.update()
 
-    get_logger().info(
-        f"Updated secret {target_secret_name} in namespace {target_secret_namespace} from secret {source_secret_name} in namespace {source_secret_namespace}."
+    logger.info(
+        f"Updated secret {target_secret_name} in namespace {target_secret_namespace} from secret {source_secret_name} in namespace {source_secret_namespace}, according to rule {rule_number} from {owner_source}."
     )