atomist / sdm-core

Event-based implementation of an SDM, which subscribes to Atomist GraphQL
Apache License 2.0
6 stars 3 forks source link

Do not close progress logs of in progress goals #206

Closed ddgenome closed 4 years ago

ddgenome commented 4 years ago

There are several types of goals that have phased execution, with the initial execution of the goal executor returning a goal that is still in progress. When this occurs, logs from subsequent phases of the execution do not appear in the progress log for the goal. This currently affects container goals and Kubernetes deployment goals.

ddgenome commented 4 years ago

It appears as though, eventually, all roads for goal execution lead through FulfillGoalOnRequested. When using a scheduler like the KubernetesGoalScheduler, the flow looks something like this:

  1. The goal enters the requested state tripping the FulfillGoalOnRequested subscription which triggers the FulfillGoalOnRequested.handler
  2. The FulfillGoalOnRequested.handler finds the KubernetesGoalScheduler and uses it to schedule the goal
  3. If the scheduling is successful, the handler returns after setting the goal state to in_process and not closing the progress log (no call to reportEndAndClose)
  4. The k8s jobs starts, which starts the SDM to run exactly one goal
  5. When the KubernetesGoalScheduler is used by the k8s implementation of the container goal, the SDM is actually run twice, first as an init container to checkout the project and then to monitor the container.
  6. When startup completes, the automation client raises the startup event, which triggers the registered event listener GoalAutomationEventListener
  7. The GoalAutomationEventListerner.startupSuccessful method constructs an event for FulfillGoalOnRequested and triggers the event
  8. That event is sent down to the worker to handle, triggering the FulfillGoalOnRequested.handle method again
  9. This time the KubernetesGoalScheduler is not found because the ATOMIST_ISOLATED_GOAL environment variable is set, so the goal is executed within the worker
  10. Whether successful or not, this results in reportEndAndClose being called, which closes the progress log and preempts further writing to the log
  11. Since the init container runs first and exits, the progress log gets closed before the monitoring container even starts.

The situation is similar for Kubernetes deployment goals. FulfillGoalOnRequested is entered twice by two different SDMs. The executor for SDM that creates the goal adds the goal data to the goal, sets the state to in_process and returns, at which point the FulfillGoalOnRequested.handle method closes the progress log. By the time the k8s-sdm spins up, the log is closed and writing to it does nothing.

ddgenome commented 4 years ago

The changes in f9b6ffb did not fix the issue. The close method is still getting called on the progress log. Looking at the log storage, all of the logs are there, but it seems rolar stops at the first log file containing "CLOSED" in the name.

ddgenome commented 4 years ago

It appears that the executeGoal function does not return any part of what the goal executor returns, https://github.com/atomist/sdm/blob/172fa73b29b4830feae4b356a92d28eabcf18dbd/lib/api-helper/goal/executeGoal.ts#L181 .

ddgenome commented 4 years ago

The change in atomist/sdm@ac1a99b with the change here atomist/sdm-core@59f669a seems to be working.

ddgenome commented 4 years ago

This is working for the Kubernetes deployments too atomist/sdm-pack-k8s#70 .