Investigate flakiness

.github/workflows/integration_test.yaml

@@ -17,7 +17,7 @@ jobs:
   # INTEGRATION_TEST_ARGS to operator-workflows automatically.
   integration-tests:
     name: Integration test with juju 3.1
-    uses: canonical/operator-workflows/.github/workflows/integration_test.yaml@main
+    uses: canonical/operator-workflows/.github/workflows/integration_test.yaml@dump-debug-logs-on-failure
     secrets: inherit
     with:
       juju-channel: 3.1/stable
@@ -31,7 +31,7 @@ jobs:
       test-timeout: 90
   openstack-interface-tests-private-endpoint:
     name: openstack interface test using private-endpoint
-    uses: canonical/operator-workflows/.github/workflows/integration_test.yaml@main
+    uses: canonical/operator-workflows/.github/workflows/integration_test.yaml@dump-debug-logs-on-failure
     secrets: inherit
     with:
       juju-channel: 3.6/stable
@@ -44,7 +44,7 @@ jobs:
       self-hosted-runner-label: stg-private-endpoint
   openstack-integration-tests-private-endpoint:
     name: Integration test using private-endpoint
-    uses: canonical/operator-workflows/.github/workflows/integration_test.yaml@main
+    uses: canonical/operator-workflows/.github/workflows/integration_test.yaml@dump-debug-logs-on-failure
     secrets: inherit
     with:
       juju-channel: 3.6/stable

github-runner-manager/src/github_runner_manager/manager/runner_scaler.py

@@ -220,7 +220,13 @@ def _reconcile_non_reactive(self, expected_quantity: int) -> _ReconcileResult:
         """
         delete_metric_stats = None
         metric_stats = self._manager.cleanup()
-        runners = self._manager.get_runners()
+        # JAVI TODO FILTER DELETED. THIS WILL GENERATE QUOTA ISSUES :(
+        from github_runner_manager.manager.cloud_runner_manager import CloudRunnerState
+        runners = self._manager.get_runners(
+            github_states = None,
+            cloud_states = [s for s in CloudRunnerState if s != CloudRunnerState.DELETED],
+        )
+        # runners = self._manager.get_runners()
         logger.info("Reconcile runners from %s to %s", len(runners), expected_quantity)
         runner_diff = expected_quantity - len(runners)
         if runner_diff > 0:
@@ -313,8 +319,7 @@ def _issue_reconciliation_metric(
 
     try:
 
-        metric_events.issue_event(
-            metric_events.Reconciliation(
+        event = metric_events.Reconciliation(
                 timestamp=time.time(),
                 flavor=reconcile_metric_data.flavor,
                 crashed_runners=reconcile_metric_data.metric_stats.get(
@@ -327,6 +332,8 @@ def _issue_reconciliation_metric(
                 duration=reconcile_metric_data.end_timestamp
                 - reconcile_metric_data.start_timestamp,
             )
-        )
+        metric_events.issue_event(event)
+        logger.info("JAVI METRIC EVENTS: %s,", event)
+        logger.info("JAVI RUNNER LIST: %s,", reconcile_metric_data.runner_list)
     except IssueMetricEventError:
         logger.exception("Failed to issue Reconciliation metric")

github-runner-manager/src/github_runner_manager/openstack_cloud/health_checks.py

@@ -189,7 +189,11 @@ def _run_health_check_cloud_init(
     """
     result: invoke.runners.Result = _execute_ssh_command(ssh_conn, "cloud-init status")
     if not result.ok:
-        logger.warning("cloud-init status command failed on %s: %s.", server_name, result.stderr)
+        logger.error("cloud-init status command failed on %s: %s.", server_name, result.stderr)
+        cloud_init_log_output_result = _execute_ssh_command(ssh_conn, "cat /var/log/cloud-init-output.log")
+        logger.error("/var/log/cloud-init-output.log stdout: %s", cloud_init_log_output_result.stdout)
+        cloud_init_log_result = _execute_ssh_command(ssh_conn, "cat /var/log/cloud-init.log")
+        logger.error("/var/log/cloud-init.log stdout: %s", cloud_init_log_result.stdout)
         return False
 
     if CloudInitStatus.DONE in result.stdout:

github-runner-manager/src/github_runner_manager/openstack_cloud/openstack_runner_manager.py

@@ -653,6 +653,10 @@ def _wait_runner_startup(self, instance: OpenstackInstance) -> None:
             logger.warning(
                 "cloud-init status command failed on %s: %s.", instance.server_name, result.stderr
             )
+            cloud_init_log_output_result = ssh_conn.run("cat /var/log/cloud-init-output.log", warn=True, timeout=60)
+            logger.error("/var/log/cloud-init-output.log stdout: %s", cloud_init_log_output_result.stdout)
+            cloud_init_log_result = ssh_conn.run("cat /var/log/cloud-init.log")
+            logger.error("/var/log/cloud-init.log stdout: %s", cloud_init_log_result.stdout, warn=True, timeout=60)
             raise RunnerStartError(f"Runner startup process not found on {instance.server_name}")
         # A short running job may have already completed and exited the runner, hence check the
         # condition via cloud-init status check.

github-runner-manager/src/github_runner_manager/templates/openstack-userdata.sh.j2

@@ -12,6 +12,8 @@ snap watch --last=auto-refresh?
 
 {% if aproxy_address %}
 snap install aproxy --edge
+snap refresh --hold=2h
+snap watch --last=auto-refresh?
 snap set aproxy proxy={{ aproxy_address }} listen=:54969
 cat << EOF > /etc/nftables.conf
 define default-ip = $(ip route get $(ip route show 0.0.0.0/0 | grep -oP 'via \K\S+') | grep -oP 'src \K\S+')

src/charm.py

@@ -336,6 +336,7 @@ def _on_upgrade_charm(self, _: UpgradeCharmEvent) -> None:
     @catch_charm_errors
     def _on_config_changed(self, _: ConfigChangedEvent) -> None:
         """Handle the configuration change."""
+        logger.info("JAVI CHARM _ON_CONFIG_CHANGED")
         state = self._setup_state()
         self._set_reconcile_timer()
 
@@ -355,6 +356,7 @@ def _on_config_changed(self, _: ConfigChangedEvent) -> None:
         if not self._get_set_image_ready_status():
             return
         if flush_and_reconcile:
+            logger.info("JAVI CHARM _ON_CONFIG_CHANGED FLUSH RECONCILE")
             logger.info("Flush and reconcile on config-changed")
             runner_scaler = self._get_runner_scaler(state)
             runner_scaler.flush(flush_mode=FlushMode.FLUSH_IDLE)
@@ -363,16 +365,19 @@ def _on_config_changed(self, _: ConfigChangedEvent) -> None:
     @catch_charm_errors
     def _on_reconcile_runners(self, _: ReconcileRunnersEvent) -> None:
         """Event handler for reconciling runners."""
+        logger.info("JAVI CHARM _on_reconcile_runners")
         self._trigger_reconciliation()
 
     @catch_charm_errors
     def _on_database_created(self, _: ops.RelationEvent) -> None:
         """Handle the MongoDB database created event."""
+        logger.info("JAVI CHARM _on_database_created")
         self._trigger_reconciliation()
 
     @catch_charm_errors
     def _on_endpoints_changed(self, _: ops.RelationEvent) -> None:
         """Handle the MongoDB endpoints changed event."""
+        logger.info("JAVI CHARM _on_endpoints_changed")
         self._trigger_reconciliation()
 
     def _trigger_reconciliation(self) -> None:
@@ -392,6 +397,7 @@ def _on_check_runners_action(self, event: ActionEvent) -> None:
         Args:
             event: The event fired on check_runners action.
         """
+        logger.info("JAVI CHARM _on_check_runners_action")
         state = self._setup_state()
 
         runner_scaler = self._get_runner_scaler(state)
@@ -414,6 +420,7 @@ def _on_reconcile_runners_action(self, event: ActionEvent) -> None:
         Args:
             event: Action event of reconciling the runner.
         """
+        logger.info("JAVI CHARM _on_reconcile_runners_action")
         self.unit.status = MaintenanceStatus("Reconciling runners")
         state = self._setup_state()
 
@@ -441,6 +448,7 @@ def _on_flush_runners_action(self, event: ActionEvent) -> None:
         Args:
             event: Action event of flushing all runners.
         """
+        logger.info("JAVI CHARM _on_flush_runners_action")
         state = self._setup_state()
 
         # Flushing mode not implemented for OpenStack yet.
@@ -465,6 +473,7 @@ def _on_update_dependencies_action(self, event: ActionEvent) -> None:
         Args:
             event: Action event of updating dependencies.
         """
+        logger.info("JAVI CHARM _on_update_dependencies_action")
         # No dependencies managed by the charm for OpenStack-based runners.
         event.set_results({"flush": False})
 
@@ -522,6 +531,7 @@ def _apt_install(self, packages: Sequence[str]) -> None:
     @catch_charm_errors
     def _on_debug_ssh_relation_changed(self, _: ops.RelationChangedEvent) -> None:
         """Handle debug ssh relation changed event."""
+        logger.info("JAVI CHARM _on_debug_ssh_relation_changed")
         self.unit.status = MaintenanceStatus("Added debug-ssh relation")
         state = self._setup_state()
 
@@ -534,6 +544,7 @@ def _on_debug_ssh_relation_changed(self, _: ops.RelationChangedEvent) -> None:
     @catch_charm_errors
     def _on_image_relation_joined(self, _: ops.RelationJoinedEvent) -> None:
         """Handle image relation joined event."""
+        logger.info("JAVI CHARM _on_image_relation_joined")
         state = self._setup_state()
 
         clouds_yaml = state.charm_config.openstack_clouds_yaml
@@ -545,6 +556,7 @@ def _on_image_relation_joined(self, _: ops.RelationJoinedEvent) -> None:
     @catch_charm_errors
     def _on_image_relation_changed(self, _: ops.RelationChangedEvent) -> None:
         """Handle image relation changed event."""
+        logger.info("JAVI CHARM _on_image_relation_changed")
         state = self._setup_state()
         self.unit.status = MaintenanceStatus("Update image for runners")
 

tests/integration/conftest.py

@@ -310,6 +310,23 @@ def runner_manager_github_client(token: str) -> GithubClient:
     return GithubClient(token=token)
 
 
+@pytest_asyncio.fixture(scope="module")
+async def openstack_model_proxy(
+    openstack_http_proxy: str,
+    openstack_https_proxy: str,
+    openstack_no_proxy: str,
+    model: Model,
+) -> None:
+    await model.set_config(
+        {
+            "juju-http-proxy": openstack_http_proxy,
+            "juju-https-proxy": openstack_https_proxy,
+            "juju-no-proxy": openstack_no_proxy,
+            "logging-config": "<root>=INFO;unit=DEBUG",
+        }
+    )
+
+
 @pytest_asyncio.fixture(scope="module")
 async def app_no_runner(
     model: Model,
@@ -432,10 +449,32 @@ async def app_openstack_runner_fixture(
         )
         await model.integrate(f"{image_builder.name}:image", f"{application.name}:image")
     await model.wait_for_idle(
-        apps=[application.name, image_builder.name], status=ACTIVE, timeout=20 * 60
+        apps=[application.name, image_builder.name], status=ACTIVE, timeout=30 * 60
     )
 
-    return application
+    # better use test-mode charm config... but let's see
+    command = "find /var/lib/juju -type f -name 'constants.py' -exec sed -i 's/^CREATE_SERVER_TIMEOUT = .*/CREATE_SERVER_TIMEOUT = 900/gI' {} \\;"
+    run_actions = await application.run(command)
+    logging.info("JAVI run_actions %s", run_actions)
+    for action_result in run_actions.actions:
+        logging.info("JAVI action_result %s", action_result)
+        action = action_result.action
+        logging.info("JAVI action %s", action)
+        # no comment...
+        action_id = action.tag
+        if action_id.startswith("action-"):
+            # strip the action- part of "action-<num>" tag
+            action_id = action_id[7:]
+        action = await model._wait_for_new("action", action_id)
+        result = await action.wait()
+        logging.info("JAVI output of one unit of CREATE_SERVER_TIMEOUT %s", result.results)
+
+    yield application
+    try:
+        logging.info("JAVI after yield in app_openstack_runner_fixture")
+        # get_file_content(unit, filename)
+    except Exception:
+        logging.exception("JAVI something failed after yield")
 
 
 @pytest_asyncio.fixture(scope="module", name="app_scheduled_events")
@@ -525,7 +564,7 @@ async def tmate_ssh_server_app_fixture(
     """tmate-ssh-server charm application related to GitHub-Runner app charm."""
     tmate_app: Application = await model.deploy("tmate-ssh-server", channel="edge")
     await app_no_wait_tmate.relate("debug-ssh", f"{tmate_app.name}:debug-ssh")
-    await model.wait_for_idle(apps=[tmate_app.name], status=ACTIVE, timeout=60 * 30)
+    await model.wait_for_idle(apps=[tmate_app.name], status=ACTIVE, timeout=60 * 20)
 
     return tmate_app
 
@@ -627,6 +666,7 @@ async def app_with_forked_repo(
     Test should ensure it returns with the application in a good state and has
     one runner.
     """
+    logging.info("JAVI forked_github_repository.full_name: %s", forked_github_repository.full_name)
     await basic_app.set_config({PATH_CONFIG_NAME: forked_github_repository.full_name})
 
     return basic_app

tests/integration/helpers/common.py

@@ -85,9 +85,11 @@ async def reconcile(app: Application, model: Model) -> None:
         app: The GitHub Runner Charm app to reconcile the runners for.
         model: The machine charm model.
     """
+    logger.info("JAVI calling common.reconcile")
     action = await app.units[0].run_action("reconcile-runners")
     await action.wait()
-    await model.wait_for_idle(apps=[app.name], status=ACTIVE)
+    # JAVI TODO put this timeout a bit bigger than the new create build timeout
+    await model.wait_for_idle(apps=[app.name], status=ACTIVE, timeout=16 * 60)
 
 
 async def deploy_github_runner_charm(
@@ -324,7 +326,7 @@ async def wait_for_completion(run: WorkflowRun, conclusion: str) -> None:
     """
     await wait_for(
         partial(_is_workflow_run_complete, run=run),
-        timeout=60 * 30,
+        timeout=60 * 20,
         check_interval=60,
     )
     # The run object is updated by _is_workflow_run_complete function above.

tests/integration/helpers/openstack.py

@@ -2,6 +2,7 @@
 #  See LICENSE file for licensing details.
 import logging
 import secrets
+import threading
 from asyncio import sleep
 from typing import Optional, TypedDict
 
@@ -17,6 +18,50 @@
 logger = logging.getLogger(__name__)
 
 
+async def javi_wait_for_idle(openstack_connection, model, *args, **kwargs) -> None:
+    """TODO.
+
+    Args:
+        openstack_connection: OpenStack connection object.
+        model: model
+        args: args
+        kwargs: kwargs
+    """
+    logger.info("javi_wait_for_idle")
+    e = threading.Event()
+
+    def _log_openstack():
+        """TODO."""
+        end_loop = False
+        while True:
+            end_loop = e.wait(20)
+            # probably not thread safe, but...
+            try:
+                servers = openstack_connection.list_servers()
+            except Exception as ex:
+                logger.exception("JAVI in log openstack thread")
+                raise ex
+            logger.info(" [ runner list ]")
+            for runner in servers:
+                logger.info(
+                    " [ runner %s ] status %s created %s updated %s",
+                    runner.name,
+                    runner.status,
+                    runner.created_at,
+                    runner.updated_at,
+                )
+            if end_loop:
+                break
+
+    try:
+        t = threading.Thread(target=_log_openstack)
+        t.start()
+        await model.wait_for_idle(*args, **kwargs)
+    finally:
+        e.set()
+        t.join()
+
+
 class OpenStackInstanceHelper:
     """Helper class to interact with OpenStack instances."""
 
@@ -179,6 +224,26 @@ async def get_runner_name(self, unit: Unit) -> str:
         assert len(runners) == 1
         return runners[0].name
 
+    def log_runners(self, unit: Unit) -> None:
+        """TODO LOG RUNNERS.
+
+        Expects only one runner to be present.
+
+        Args:
+            unit: The GitHub Runner Charm unit to get the runner name for.
+        """
+        runners = self._get_runners(unit)
+        logger.info("[ list of runners for unit %s]", unit)
+        for runner in runners:
+            logger.info(
+                " [ runner %s ] status %s created %s updated %s",
+                runner.name,
+                runner.status,
+                runner.created_at,
+                runner.updated_at,
+            )
+        logger.info("[ end list of runners for unit %s]")
+
     async def delete_single_runner(self, unit: Unit) -> None:
         """Delete the only runner.