Felis/internal/api/schedulerunner.go

package api

import (
	"context"
	"errors"
	"fmt"
	"log"
	"math"
	"strings"
	"time"

	"felis.lolicon.best/internal/apis/felis/v1alpha1"
	"felis.lolicon.best/internal/maintenance"
)

// The schedule runner. cmd/felis calls RunSchedules every few seconds; each
// call warns the players about the runs coming up, fires the runs that are
// due and moves every run in progress one step on. All of its state is in
// server_schedules, so a felis-api restart picks a restart or backup up where
// it was.
//
// A command, stop or start is one step. A restart stops the server (runStopping)
// and starts it once it is down (runStarting). A backup of a running server
// stops it, takes a backup once the world volume is free (runBackingUp), waits
// for the backup Job and starts the server again; a backup of a stopped server
// leaves it stopped. Each step gives up after its own wait, and a run that took
// the server down tries to bring it back when it gives up.

// Run steps (Schedule.RunState).
const (
	runClaimed   = "claimed"
	runStopping  = "stopping"
	runBackingUp = "backing_up"
	runStarting  = "starting"
)

const (
	// scheduleMissGrace is how late a run may still start: felis-api back from
	// a short restart catches up, and a run hours late is dropped as missed.
	scheduleMissGrace = 10 * time.Minute
	// claimedStale is how long a run may sit in its first step before it is
	// taken for one whose felis-api stopped mid-step. The first step is a few
	// API calls and at most one RCON round trip.
	claimedStale = 2 * time.Minute
	// stopWait is how long a run waits for the server to stop and its world
	// volume to come free. A pod saving a big world takes a while.
	stopWait = 15 * time.Minute
	// backupWait is how long a run waits for its backup Job: past the Job's own
	// deadline ([archive] backup Job deadline, 30m by default).
	backupWait = 45 * time.Minute
	// startWait is how long a run keeps trying to start the server again while
	// the cluster is at its running cap or the world volume is still busy.
	startWait = 15 * time.Minute
	// backupJobSkew is how much earlier than the step the backup Job's creation
	// stamp may read: felis-api's clock and the API server's differ a little.
	backupJobSkew = 2 * time.Minute
	// scheduleWarnHorizon is the longest warning lead time, in minutes.
	scheduleWarnHorizon = 30
)

// Audit identity of a run. Each run leaves one schedule.run row when it ends.
const (
	scheduleActor     = "scheduler"
	scheduleRunAction = "schedule.run"
)

// RunSchedules warns about, fires and advances the schedules once. A schedule
// that fails is logged and left for the next call; it never holds up the rest.
func (a *API) RunSchedules(ctx context.Context) error {
	if a.Schedules == nil {
		return nil
	}
	now := a.now()
	due, err := a.Schedules.DueSchedules(ctx, now.Add(scheduleWarnHorizon*time.Minute))
	if err != nil {
		return fmt.Errorf("list the due schedules: %w", err)
	}
	for i := range due {
		d := &due[i]
		if err := a.tickSchedule(ctx, d, now); err != nil {
			log.Printf("api: schedule %d of %s: %v", d.ID, d.Server, err)
		}
	}
	return nil
}

// tickSchedule does what one due schedule needs now.
func (a *API) tickSchedule(ctx context.Context, d *DueSchedule, now time.Time) error {
	s := &d.Schedule
	if s.RunState != "" {
		return a.advanceRun(ctx, s, now)
	}
	// Somebody else's server now: their commands must not run on it. Saving
	// the schedule again (PUT) hands it to the new owner.
	if d.ServerOwner != s.OwnerID {
		_, err := a.Schedules.DisableSchedule(ctx, s.ID,
			"the server has a new owner since this schedule was saved; save it again to use it")
		return err
	}
	due := *s.NextRunAt // set on every enabled schedule DueSchedules returns idle
	if now.Before(due) {
		return a.warnRun(ctx, s, due, now)
	}
	next := s.nextRun(now)
	if now.Sub(due) > scheduleMissGrace {
		_, err := a.Schedules.MissScheduleRun(ctx, s.ID, due, next,
			"felis-api was not running at the scheduled time")
		return err
	}
	ok, err := a.Schedules.ClaimScheduleRun(ctx, s.ID, &due, &next, now)
	if err != nil || !ok {
		return err
	}
	return a.beginRun(ctx, s)
}

// warnRun tells the players on the server that a restart, stop or backup is
// coming, once per run, when its warning time has come.
func (a *API) warnRun(ctx context.Context, s *Schedule, due, now time.Time) error {
	lead := time.Duration(s.WarnMinutes) * time.Minute
	if now.Before(due.Add(-lead)) || a.Console == nil {
		return nil // no warning, or not yet
	}
	info, err := a.Cluster.GetServer(ctx, s.Server)
	if err != nil {
		return err
	}
	if !info.Ready {
		return nil
	}
	ok, err := a.Schedules.WarnScheduleRun(ctx, s.ID, due)
	if err != nil || !ok {
		return err
	}
	// Warned late (felis-api was restarting at the warning time): say how long
	// is really left.
	minutes := int(math.Ceil(due.Sub(now).Minutes()))
	if _, err := a.Console.RunCommand(ctx, s.Server, "say "+scheduleWarning(s.Action, minutes)); err != nil {
		return fmt.Errorf("warn the players: %w", err)
	}
	return nil
}

// scheduleWarning is the in-game line announcing a run minutes ahead, in both
// panel languages.
func scheduleWarning(action string, minutes int) string {
	switch action {
	case ScheduleRestart:
		return fmt.Sprintf("[Felis] 服务器将在 %d 分钟后重启 / Server restarts in %d min", minutes, minutes)
	case ScheduleStop:
		return fmt.Sprintf("[Felis] 服务器将在 %d 分钟后关闭 / Server stops in %d min", minutes, minutes)
	default:
		return fmt.Sprintf("[Felis] 服务器将在 %d 分钟后暂停做备份，完成后自动恢复 / Server pauses for a backup in %d min and comes back after", minutes, minutes)
	}
}

// beginRun takes the first step of a run just claimed (runClaimed).
func (a *API) beginRun(ctx context.Context, s *Schedule) error {
	finish := func(result, detail string) error { return a.finishRun(ctx, s, runClaimed, result, detail) }
	info, err := a.Cluster.GetServer(ctx, s.Server)
	if errors.Is(err, ErrNotFound) {
		return finish(ScheduleSkipped, "the server no longer exists")
	}
	if err != nil {
		return finish(ScheduleFailed, "could not read the server: "+err.Error())
	}
	running := info.DesiredState == string(v1alpha1.DesiredRunning)

	switch s.Action {
	case ScheduleCommand:
		if !info.Ready {
			return finish(ScheduleSkipped, "the server was not running")
		}
		if a.Console == nil {
			return finish(ScheduleFailed, "the console is not configured")
		}
		out, err := a.Console.RunCommand(ctx, s.Server, s.Command)
		if errors.Is(err, ErrConsoleUnavailable) {
			return finish(ScheduleFailed, "the server console could not be reached")
		}
		if err != nil {
			return finish(ScheduleFailed, "the command failed: "+err.Error())
		}
		return finish(ScheduleOK, stripFormatting(out))

	case ScheduleStop:
		if !running {
			return finish(ScheduleSkipped, "the server was already stopped")
		}
		if err := a.Cluster.SetDesiredState(ctx, s.Server, v1alpha1.DesiredStopped); err != nil {
			return finish(ScheduleFailed, "could not stop the server: "+err.Error())
		}
		return finish(ScheduleOK, "")

	case ScheduleStart:
		if running && info.Phase != string(v1alpha1.PhaseFailed) {
			return finish(ScheduleSkipped, "the server was already running")
		}
		why, _, err := a.startScheduled(ctx, s.Server)
		if err != nil {
			return finish(ScheduleFailed, "could not start the server: "+err.Error())
		}
		if why != "" {
			return finish(ScheduleSkipped, why)
		}
		return finish(ScheduleOK, "")

	case ScheduleRestart:
		if !running {
			return finish(ScheduleSkipped, "the server was not running")
		}
		return a.stopForRun(ctx, s, true)

	case ScheduleBackup:
		if _, ok := a.Backuper.(ScheduledBackuper); !ok {
			return finish(ScheduleFailed, "backups are not configured")
		}
		if limit := a.BackupStoreCap; limit > 0 {
			used, err := a.Repo.BackupStoreBytes(ctx)
			if err != nil {
				return finish(ScheduleFailed, "could not read the backup store size: "+err.Error())
			}
			if used >= limit {
				return finish(ScheduleFailed, "the backup store is full; ask an administrator to free space")
			}
		}
		exists, err := a.Cluster.WorldVolumeExists(ctx, s.Server)
		if err != nil {
			return finish(ScheduleFailed, "could not look up the world volume: "+err.Error())
		}
		if !exists {
			return finish(ScheduleSkipped, "the server has no world yet")
		}
		if running {
			return a.stopForRun(ctx, s, true)
		}
		// Already stopped: back it up as soon as the world volume is free, and
		// leave it stopped afterwards.
		if ok, err := a.Schedules.AdvanceScheduleRun(ctx, s.ID, runClaimed, runStopping, false, "", "", a.now()); err != nil || !ok {
			return err
		}
		s.RunState, s.RunResume, s.RunStepAt = runStopping, false, ptrTime(a.now())
		return a.advanceRun(ctx, s, a.now())
	}
	return finish(ScheduleFailed, "unknown action "+s.Action)
}

// stopForRun records the stop step and then stops the server, in that order: a
// felis-api that dies between the two leaves a running server in runStopping,
// which the next call reads as someone having started it, and nothing is lost.
func (a *API) stopForRun(ctx context.Context, s *Schedule, resume bool) error {
	now := a.now()
	if ok, err := a.Schedules.AdvanceScheduleRun(ctx, s.ID, runClaimed, runStopping, resume, "", "", now); err != nil || !ok {
		return err
	}
	if err := a.Cluster.SetDesiredState(ctx, s.Server, v1alpha1.DesiredStopped); err != nil {
		return a.finishRun(ctx, s, runStopping, ScheduleFailed, "could not stop the server: "+err.Error())
	}
	return nil
}

// advanceRun moves a run in progress on by one step, or leaves it waiting.
func (a *API) advanceRun(ctx context.Context, s *Schedule, now time.Time) error {
	waited := now.Sub(*s.RunStepAt)
	switch s.RunState {
	case runClaimed:
		if waited < claimedStale {
			return nil // its first step is running right now
		}
		return a.finishRun(ctx, s, runClaimed, ScheduleFailed, "felis-api stopped in the middle of this run")
	case runStopping:
		return a.advanceStopping(ctx, s, waited)
	case runBackingUp:
		return a.advanceBackingUp(ctx, s, waited)
	case runStarting:
		return a.advanceStarting(ctx, s, waited)
	}
	return a.finishRun(ctx, s, s.RunState, ScheduleFailed, "unknown run step "+s.RunState)
}

// advanceStopping waits for the server to go down. A restart then starts it;
// a backup takes the world volume and starts the backup Job.
func (a *API) advanceStopping(ctx context.Context, s *Schedule, waited time.Duration) error {
	info, err := a.Cluster.GetServer(ctx, s.Server)
	if errors.Is(err, ErrNotFound) {
		return a.finishRun(ctx, s, runStopping, ScheduleSkipped, "the server no longer exists")
	}
	if err != nil {
		return err
	}
	// Only this run stops the server; wanted running again means a person (or
	// a player's join) started it meanwhile, and their start stands.
	if info.DesiredState == string(v1alpha1.DesiredRunning) {
		return a.finishRun(ctx, s, runStopping, ScheduleSkipped, "someone started the server before the run finished")
	}
	giveUp := func(detail string) error {
		if waited < stopWait {
			return nil
		}
		if s.RunResume {
			if err := a.Cluster.SetDesiredState(ctx, s.Server, v1alpha1.DesiredRunning); err == nil {
				detail += "; it was started again"
			}
		}
		return a.finishRun(ctx, s, runStopping, ScheduleFailed, detail)
	}

	if s.Action == ScheduleRestart {
		if info.Phase != string(v1alpha1.PhaseStopped) {
			return giveUp("the server did not stop within 15 minutes")
		}
		if ok, err := a.Schedules.AdvanceScheduleRun(ctx, s.ID, runStopping, runStarting, s.RunResume, "", "", a.now()); err != nil || !ok {
			return err
		}
		s.RunState, s.RunStepAt = runStarting, ptrTime(a.now())
		return a.advanceStarting(ctx, s, 0)
	}

	b, ok := a.Backuper.(ScheduledBackuper)
	if !ok {
		return a.finishRun(ctx, s, runStopping, ScheduleFailed, "backups are not configured")
	}
	switch err := a.Cluster.AcquireMaintenance(ctx, s.Server, maintenance.KindBackup); {
	case errors.Is(err, ErrNotStopped):
		return giveUp("the server did not stop within 15 minutes")
	case errors.Is(err, ErrMaintenanceInProgress):
		return giveUp("another operation kept the world busy for 15 minutes")
	case errors.Is(err, ErrNotFound):
		return a.finishRun(ctx, s, runStopping, ScheduleSkipped, "the server no longer exists")
	case err != nil:
		return err
	}
	err = b.BackupScheduled(ctx, s.Server, s.OwnerID)
	// Once the Job exists it holds the world; the lock only covered the gap.
	if rerr := a.Cluster.ReleaseMaintenance(context.WithoutCancel(ctx), s.Server); rerr != nil {
		log.Printf("api: release the maintenance lock on %s: %v (it lapses after %s)", s.Server, rerr, maintenance.Grace)
	}
	if err != nil {
		detail := "could not start the backup: " + err.Error()
		if s.RunResume {
			if serr := a.Cluster.SetDesiredState(ctx, s.Server, v1alpha1.DesiredRunning); serr == nil {
				detail += "; the server was started again"
			}
		}
		return a.finishRun(ctx, s, runStopping, ScheduleFailed, detail)
	}
	log.Printf("api: schedule %d started a backup of %s", s.ID, s.Server)
	_, err = a.Schedules.AdvanceScheduleRun(ctx, s.ID, runStopping, runBackingUp, s.RunResume, "", "", a.now())
	return err
}

// advanceBackingUp waits for the backup Job and records how it ended; a run
// that stopped a running server then starts it again.
func (a *API) advanceBackingUp(ctx context.Context, s *Schedule, waited time.Duration) error {
	result, detail := ScheduleOK, ""
	if a.JobStatus != nil {
		jobs, err := a.JobStatus.LatestJobs(ctx, s.Server)
		if err != nil {
			return err
		}
		var job *AsyncJob
		for i := range jobs {
			j := &jobs[i]
			if j.Scheduled && !j.StartedAt.Before(s.RunStepAt.Add(-backupJobSkew)) {
				job = j
				break // newest first
			}
		}
		switch {
		case job == nil && waited < backupJobSkew:
			return nil // not listed yet
		case job == nil:
			result, detail = ScheduleFailed, "the backup Job is gone before it could be checked; see the Backups page"
		case job.State == "running" && waited < backupWait:
			return nil
		case job.State == "running":
			result, detail = ScheduleFailed, "the backup did not finish within 45 minutes"
		case job.State == "failed":
			result, detail = ScheduleFailed, strings.TrimSpace("the backup failed: "+job.Message)
		}
	}
	if !s.RunResume {
		return a.finishRun(ctx, s, runBackingUp, result, detail)
	}
	if ok, err := a.Schedules.AdvanceScheduleRun(ctx, s.ID, runBackingUp, runStarting, true, result, detail, a.now()); err != nil || !ok {
		return err
	}
	s.RunState, s.RunStepAt, s.LastResult, s.LastDetail = runStarting, ptrTime(a.now()), result, detail
	return a.advanceStarting(ctx, s, 0)
}

// advanceStarting brings the server back up after a restart's stop or a
// backup. The outcome recorded so far (the backup's) is kept when it starts.
func (a *API) advanceStarting(ctx context.Context, s *Schedule, waited time.Duration) error {
	why, retry, err := a.startScheduled(ctx, s.Server)
	if errors.Is(err, ErrNotFound) {
		return a.finishRun(ctx, s, runStarting, ScheduleSkipped, "the server no longer exists")
	}
	if err != nil {
		return err
	}
	if why == "" {
		result, detail := s.LastResult, s.LastDetail
		if result == "" {
			result = ScheduleOK
		}
		return a.finishRun(ctx, s, runStarting, result, detail)
	}
	if retry && waited < startWait {
		return nil
	}
	detail := "could not start the server again: " + why
	if s.LastResult == ScheduleFailed {
		detail = s.LastDetail + "; " + detail
	}
	return a.finishRun(ctx, s, runStarting, ScheduleFailed, detail)
}

// startScheduled starts a server for a run: the wake path without the
// per-player cooldown. why names what kept it stopped ("" once it is wanted
// running), and retry says whether that may clear by itself.
func (a *API) startScheduled(ctx context.Context, name string) (why string, retry bool, err error) {
	rec, err := a.Repo.ServerByName(ctx, name)
	if err != nil {
		return "", false, err
	}
	if rec.Retire != nil {
		return "the server is being given up or deleted", false, nil
	}
	info, err := a.Cluster.GetServer(ctx, name)
	if err != nil {
		return "", false, err
	}
	policy, _, err := a.readWakePolicy(ctx)
	if err != nil {
		return "", false, err
	}
	ok, err := a.withinRunningCap(ctx, info, policy.MaxRunningServers)
	if err != nil {
		return "", false, err
	}
	if !ok {
		return "the cluster is at its running-server cap", true, nil
	}
	// A start that Failed is started over, as a person's start does (handleStart).
	if info.Phase == string(v1alpha1.PhaseFailed) && info.DesiredState == string(v1alpha1.DesiredRunning) {
		err = a.Cluster.RetryStart(ctx, name)
	} else {
		err = a.Cluster.SetDesiredState(ctx, name, v1alpha1.DesiredRunning)
	}
	var busy *MaintenanceBusyError
	if errors.As(err, &busy) {
		return "the world is busy with " + maintenanceLabel(busy.Kind), true, nil
	}
	return "", false, err
}

// finishRun ends a run at step from and audits it.
func (a *API) finishRun(ctx context.Context, s *Schedule, from, result, detail string) error {
	detail = truncateUTF8(detail, maxScheduleDetail)
	ok, err := a.Schedules.FinishScheduleRun(ctx, s.ID, from, result, detail)
	if err != nil || !ok {
		return err
	}
	a.writeAudit(ctx, AuditEntry{
		Actor: scheduleActor, Source: scheduleActor, Action: scheduleRunAction, ServerName: s.Server,
		Payload: auditPayload(map[string]any{"schedule": s.ID, "action": s.Action, "result": result, "detail": detail}),
	})
	return nil
}

// stripFormatting drops Minecraft's section-sign formatting codes from a
// console reply and trims it.
func stripFormatting(s string) string {
	var b strings.Builder
	skip := false
	for _, c := range s {
		switch {
		case skip:
			skip = false
		case c == '§':
			skip = true
		default:
			b.WriteRune(c)
		}
	}
	return strings.TrimSpace(b.String())
}

func ptrTime(t time.Time) *time.Time { return &t }