| 1 | package console |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "crypto/ed25519" |
| 6 | "crypto/sha256" |
| 7 | "encoding/hex" |
| 8 | "encoding/json" |
| 9 | "errors" |
| 10 | "fmt" |
| 11 | "log" |
| 12 | "os" |
| 13 | "time" |
| 14 | |
| 15 | "github.com/carlosframework/platform/internal/alerting" |
| 16 | "github.com/carlosframework/platform/internal/hostclaim" |
| 17 | "github.com/carlosframework/platform/internal/hostfence" |
| 18 | "github.com/carlosframework/platform/internal/hostops" |
| 19 | "github.com/carlosframework/platform/internal/moves" |
| 20 | "github.com/carlosframework/platform/internal/park" |
| 21 | "github.com/carlosframework/platform/internal/provision" |
| 22 | ) |
| 23 | |
| 24 | // The console's move pass (moves Plan 5 Task 7, spec §7.5, §7.10, §7.11, |
| 25 | // §13; Paul's ruling M4). It is the moves body of claim Plan 10's |
| 26 | // Recovery.Moves hook: the recovery pass (ControlWriter.RecoveryPass) calls |
| 27 | // movesRecovery once per claim of a move kind, with a MoveRecoveryGrant bound |
| 28 | // to that claim, its move registration and the exact record it observed. |
| 29 | // ConfigureClaimRuntime binds it only with the moves switch on. |
| 30 | // |
| 31 | // Each call reads the claim and the record again through the console's store, |
| 32 | // gives up if either moved on since the grant's observation (the next pass |
| 33 | // observes afresh), decides at most one action (decideMoveRecovery) and takes |
| 34 | // it. The grant is spent by its first write, so one observation is never two |
| 35 | // writes. In the order the decision tries them: |
| 36 | // |
| 37 | // 1. An orphan: a claim of a move kind whose record carries neither the move |
| 38 | // nor its outcome. A moving claim before the seal (the request door's |
| 39 | // record write was lost) is left for ten minutes, then its start effect |
| 40 | // is settled without the request's handle (ResolveStart, K3), and on a |
| 41 | // later pass, with the start settled not applied, released |
| 42 | // (release-not-applied). Any other orphan is paged, once, and left: an |
| 43 | // operation past the seal with no record is an incident. |
| 44 | // 2. A source terminated before the flip (K13): Convert with the source's |
| 45 | // termination fence, which writes the record's relocation decision on |
| 46 | // one pass and converts the claim to relocating on the next. |
| 47 | // 3. The six-hour abort (K18): a move still preparing moves.AbortAfter |
| 48 | // after its request is aborted through ConsoleMove(ConsoleMoveAbort); |
| 49 | // the source's own abort (movesabort.go) takes it from there. |
| 50 | // 4. The claim half the record decided (§7.5, Review Focus 5): flip, |
| 51 | // commit or rollback, with the target's fence between the flip and the |
| 52 | // rest (below). Anything else is left alone. |
| 53 | // 5. The deadline: a landing past the earlier of its cut and landing |
| 54 | // deadlines is rolled back by the record (J11, J9's recorded reason). |
| 55 | // 6. A lost target released with nothing of its box or region owed: |
| 56 | // target_parked_at, through the |
| 57 | // record-sequenced recovery grant (StampLostMoveTargetParked) |
| 58 | // (p10 Task G). |
| 59 | // 7. A close whose stamps are in and whose op owes nothing: the record's |
| 60 | // close (close, rolled-back-close or revert-close). The boxes close on |
| 61 | // their own in the pass the close becomes due; the console writes it |
| 62 | // only when it has been due for moveCloseGrace, and pages that it did. |
| 63 | // An abort is never closed here (fix round 1, ruling 1): only the |
| 64 | // source closes it, after it retired its own snapshots, receipts, |
| 65 | // ledger and journal (movesabort.go), and nothing on the record shows |
| 66 | // that it did. An abort due past the lane's horizon (the claim's |
| 67 | // quiet_after for the target region) plus moveCloseGrace is paged |
| 68 | // once, and left to the source. |
| 69 | // 8. The release: the record closed (LastMove names the op) and the claim |
| 70 | // not yet released. This is the second half of every record-first close |
| 71 | // (ruling M4); after a box crashed between the halves, only this pass |
| 72 | // writes it, because no box visits a record without a move. |
| 73 | // |
| 74 | // The target's fence (moves after claim Plan 12, Task 5, ruling Q8). A |
| 75 | // landing claim before its commit, or a restoring claim, whose target box was |
| 76 | // terminated has its regional worker's termination fence at |
| 77 | // control/box-fences/<target enrollment>.json. The grant's |
| 78 | // ReleaseFencedTarget takes one step of it per call, record first: on a |
| 79 | // landing it rolls the record back with the target lost under the fence |
| 80 | // (RollbackTargetFenced), or on a rollback marks the target lost; then the |
| 81 | // claim's release, which rolls a landing claim back and consumes the fence in |
| 82 | // one write; then the record's loss commit (released, the fence as its |
| 83 | // evidence). The fence comes after the flip (the grant refuses a moving |
| 84 | // claim) and ahead of the claim's rollback half and the deadline's rollback, |
| 85 | // because the grant writes both halves itself. Once the claim carries the |
| 86 | // consumed fence, the reference is the claim's (ConsumedMoveTargetFence), |
| 87 | // never the bucket's; and once the record carries it as both its loss and its |
| 88 | // evidence, the pass stops calling it. A dirty target (one that released with |
| 89 | // writes the source does not have) cannot be finished from a dead box: the |
| 90 | // grant refuses it after it verified the fence, the pass pages once that an |
| 91 | // operator must declare the target lost, and leaves it for J4. The page rests |
| 92 | // only on the grant's verified-dirty outcome, never on a bare ErrPending. Its fence |
| 93 | // comes after the claim's rollback half, which the grant does not take for |
| 94 | // it. The console logs the fence's record writes, and its claim rollback, as |
| 95 | // its own move writes, from the grant's outcome (the write's own evidence). |
| 96 | // |
| 97 | // Pages (§13) go through alerting.Page on the sinks cmd/console arms, best |
| 98 | // effort: a rollback waiting past its release deadline (an incident, again |
| 99 | // only a full hour after the last attempt), a move preparing for over an |
| 100 | // hour, an orphan past the seal (an incident), an overdue close the console |
| 101 | // wrote, an overdue abort the console leaves to its source, and a dirty |
| 102 | // fenced target left for J4 (an incident) (each once). |
| 103 | // The rate limit is durable: the last attempt's time is kept per finding in |
| 104 | // the console's store (move_pages, fix round 1 ruling 3), written whether or |
| 105 | // not delivery worked, so a restarted console keeps the spacing. |
| 106 | // |
| 107 | // A relocating claim is region HA's, and the pass does nothing for it. |
| 108 | |
| 109 | const ( |
| 110 | // moveOrphanAfter is how old, by Op.StartedAt, a moving claim with no |
| 111 | // record move must be before the pass settles its start. |
| 112 | moveOrphanAfter = 10 * time.Minute |
| 113 | // movePreparingPage is how long a move may prepare before it pages |
| 114 | // (§13: 60 minutes with no promotable round). |
| 115 | movePreparingPage = time.Hour |
| 116 | // moveCloseGrace is how long a close must have been due before the |
| 117 | // console writes it instead of the boxes. |
| 118 | moveCloseGrace = 10 * time.Minute |
| 119 | ) |
| 120 | |
| 121 | type moveRecoveryAction string |
| 122 | |
| 123 | const ( |
| 124 | moveActNone moveRecoveryAction = "" |
| 125 | moveActResolveStart moveRecoveryAction = "resolve-start" |
| 126 | moveActConvert moveRecoveryAction = "convert" |
| 127 | moveActAbort moveRecoveryAction = "abort" |
| 128 | moveActClaim moveRecoveryAction = "claim" |
| 129 | moveActRecord moveRecoveryAction = "record" |
| 130 | moveActStampLost moveRecoveryAction = "stamp-lost" |
| 131 | // moveActFence is one step of the target's termination fence, through |
| 132 | // the grant's ReleaseFencedTarget (Q8). |
| 133 | moveActFence moveRecoveryAction = "fence" |
| 134 | moveActClose moveRecoveryAction = "close" |
| 135 | // moveActAbortOverdue writes nothing: an abort due to close, which only |
| 136 | // its source may close, is checked for being overdue and paged. |
| 137 | moveActAbortOverdue moveRecoveryAction = "abort-overdue" |
| 138 | ) |
| 139 | |
| 140 | type movePageKind string |
| 141 | |
| 142 | const ( |
| 143 | movePageReleaseDeadline movePageKind = "release-deadline" |
| 144 | movePagePreparing movePageKind = "preparing" |
| 145 | movePageOrphan movePageKind = "orphan" |
| 146 | movePageCloseOverdue movePageKind = "close-overdue" |
| 147 | movePageAbortOverdue movePageKind = "abort-overdue" |
| 148 | // movePageTargetFencedDirty is a dirty target whose fence the grant |
| 149 | // refused: left for J4 (Q8). |
| 150 | movePageTargetFencedDirty movePageKind = "target-fenced-dirty" |
| 151 | ) |
| 152 | |
| 153 | // moveRecoveryInput is what one observation saw. Start is the op's move-start |
| 154 | // effect, read only for a moving claim with no record move; Fence is the |
| 155 | // source's termination fence, read only for a moving claim. TargetFence is |
| 156 | // the target's (Q8), read only for a landing claim before its commit or a |
| 157 | // restoring claim: the claim's consumed fence when it carries one |
| 158 | // (TargetFenceConsumed), otherwise the bucket's. |
| 159 | type moveRecoveryInput struct { |
| 160 | Now time.Time |
| 161 | Claim *hostclaim.Claim |
| 162 | Rec provision.Record |
| 163 | Start *hostops.Effect |
| 164 | Fence *hostclaim.FenceRef |
| 165 | TargetFence *hostclaim.FenceRef |
| 166 | TargetFenceConsumed bool |
| 167 | } |
| 168 | |
| 169 | // moveRecoveryDecision is at most one action, with the grant action it |
| 170 | // names, and the pages the observation calls for. |
| 171 | type moveRecoveryDecision struct { |
| 172 | Action moveRecoveryAction |
| 173 | Claim hostops.MoveRecoveryClaimAction |
| 174 | Record hostops.MoveRecoveryRecordAction |
| 175 | Pages []movePageKind |
| 176 | } |
| 177 | |
| 178 | // decideMoveRecovery is the pass's whole policy, on values (see the file |
| 179 | // comment for the order). |
| 180 | func decideMoveRecovery(in moveRecoveryInput) moveRecoveryDecision { |
| 181 | var d moveRecoveryDecision |
| 182 | c := in.Claim |
| 183 | if c == nil || c.Holder == nil || c.Op.ID == "" || c.Op.Kind == hostclaim.KindRelocating { |
| 184 | return d |
| 185 | } |
| 186 | op, rec, m := c.Op, in.Rec, in.Rec.Move |
| 187 | sealed := op.Kind == hostclaim.KindMoving && op.Phase == hostclaim.PhaseSealed |
| 188 | if m == nil || m.Legacy() || m.ID != op.ID { |
| 189 | if m != nil { |
| 190 | return d // another move's record: not this op's to settle |
| 191 | } |
| 192 | if rec.LastMove != nil && rec.LastMove.ID == op.ID { |
| 193 | d.Action, d.Claim = moveActClaim, hostops.RecoveryMoveRelease |
| 194 | return d |
| 195 | } |
| 196 | if op.Kind != hostclaim.KindMoving || op.Phase != hostclaim.PhaseMoving { |
| 197 | d.Pages = append(d.Pages, movePageOrphan) |
| 198 | return d |
| 199 | } |
| 200 | if op.StartedAt.IsZero() || in.Now.Before(op.StartedAt.Add(moveOrphanAfter)) || in.Start == nil { |
| 201 | return d |
| 202 | } |
| 203 | switch { |
| 204 | case in.Start.State == "uncertain": |
| 205 | d.Action = moveActResolveStart |
| 206 | case in.Start.State == "complete" && in.Start.ResultReference == "not-applied": |
| 207 | d.Action, d.Claim = moveActClaim, hostops.RecoveryMoveReleaseNotApplied |
| 208 | } |
| 209 | return d |
| 210 | } |
| 211 | if m.Incarnation != c.Holder.Incarnation { |
| 212 | return d |
| 213 | } |
| 214 | rb := m.Rollback |
| 215 | if m.State == provision.MoveRollingBack && rb != nil && rb.ReleaseDeadline != nil && in.Now.After(*rb.ReleaseDeadline) && rb.TargetPhase == provision.RbTargetReleasing { |
| 216 | d.Pages = append(d.Pages, movePageReleaseDeadline) |
| 217 | } |
| 218 | if m.State == provision.MovePreparing && !m.RequestedAt.IsZero() && !in.Now.Before(moves.PreparingSince(m).Add(movePreparingPage)) { |
| 219 | d.Pages = append(d.Pages, movePagePreparing) |
| 220 | } |
| 221 | owed := owedUnderOp(c, op.ID, nil) |
| 222 | fence, fenceDirty := targetFenceStep(in) |
| 223 | |
| 224 | switch { |
| 225 | case op.Kind == hostclaim.KindMoving && in.Fence != nil && (m.State == provision.MovePreparing || m.State == provision.MoveReady || m.State == provision.MoveCutting || m.State == provision.MoveRelocating): |
| 226 | d.Action = moveActConvert |
| 227 | case op.Kind == hostclaim.KindMoving && op.Phase == hostclaim.PhaseMoving && moves.AbortDue(rec, in.Now): |
| 228 | d.Action = moveActAbort |
| 229 | case m.State == provision.MoveLanding && m.FlippedAt != nil && rec.Region == m.To && sealed: |
| 230 | d.Action, d.Claim = moveActClaim, hostops.RecoveryMoveFlip |
| 231 | case fence && !fenceDirty: |
| 232 | d.Action = moveActFence |
| 233 | case m.State == provision.MoveCommitted && m.CommittedAt != nil && m.FlippedAt != nil && rec.Region == m.To && op.Kind == hostclaim.KindLanding && op.Phase == hostclaim.PhaseLandingProbed: |
| 234 | d.Action, d.Claim = moveActClaim, hostops.RecoveryMoveCommit |
| 235 | case m.State == provision.MoveRollingBack && rb != nil && rec.Region == m.From && (op.Kind == hostclaim.KindLanding && op.Phase != hostclaim.PhaseCommitted || sealed): |
| 236 | d.Action, d.Claim = moveActClaim, hostops.RecoveryMoveRollback |
| 237 | case m.State == provision.MoveLanding && op.Kind == hostclaim.KindLanding && op.Phase != hostclaim.PhaseCommitted && moveDeadlinePassed(m, in.Now): |
| 238 | d.Action, d.Record = moveActRecord, hostops.RecoveryMoveDeadlineRollback |
| 239 | case fence: |
| 240 | // A dirty target: after the claim's rollback half, which the grant |
| 241 | // does not take for it. The grant verifies the fence and refuses it; |
| 242 | // the pass pages (movesRecovery). |
| 243 | d.Action = moveActFence |
| 244 | case m.State == provision.MoveRollingBack && rb != nil && rb.TargetPhase == provision.RbTargetReleased && !rb.Dirty && rb.TargetParkedAt == nil && |
| 245 | hostclaim.LostMoveTargetParked(c, park.PlacementRegion(m.To)): |
| 246 | d.Action = moveActStampLost |
| 247 | case owed > 0: |
| 248 | case m.State == provision.MoveCommitted && m.OpenedAt != nil && m.SourceParkedAt != nil && rec.Region == m.To && op.Kind == hostclaim.KindLanding && op.Phase == hostclaim.PhaseCommitted: |
| 249 | d.Action, d.Record = moveActClose, hostops.RecoveryMoveClose |
| 250 | case m.State == provision.MoveRollingBack && rb != nil && rb.RecoveredAt != nil && rb.OpenedAt != nil && rb.TargetParkedAt != nil && rec.Region == m.From && op.Kind == hostclaim.KindRestoring && op.Phase == hostclaim.PhaseOpened: |
| 251 | d.Action, d.Record = moveActClose, hostops.RecoveryMoveRolledBackClose |
| 252 | case m.State == provision.MoveReverting && m.ReopenedAt != nil && rec.Region == m.From && op.Kind == hostclaim.KindReverting && op.Phase == hostclaim.PhaseOpened: |
| 253 | d.Action, d.Record = moveActClose, hostops.RecoveryMoveRevertClose |
| 254 | case m.State == provision.MoveAborting && op.Kind == hostclaim.KindMoving && op.Phase == hostclaim.PhaseAborting: |
| 255 | d.Action = moveActAbortOverdue |
| 256 | } |
| 257 | return d |
| 258 | } |
| 259 | |
| 260 | // targetFenceStep reports whether the target's fence (in.TargetFence) has a |
| 261 | // step left for the grant's ReleaseFencedTarget, and whether the step is a |
| 262 | // dirty target's, which the grant refuses and the pass leaves for J4 (Q8). |
| 263 | // The record's regions are compared as the grant compares them, code with |
| 264 | // code. |
| 265 | // |
| 266 | // Consumed (the claim's release is done), the one step left is the record's |
| 267 | // loss commit: the target lost under this fence. Once the record carries the |
| 268 | // fence as its loss and its evidence, or the target released on its own |
| 269 | // evidence, the fence is spent. Not yet consumed, a step is one the grant |
| 270 | // would take: a landing's rollback; a rollback whose target still holds |
| 271 | // something the source needs (releasing, returning, or released dirty) is |
| 272 | // marked lost; the target lost under this fence, the claim's release; or a |
| 273 | // target that released clean while the claim still waits on it |
| 274 | // (restoring/releasing under the target), the claim's release. A target |
| 275 | // lost under another loss (J4's declaration) is not the fence's. |
| 276 | func targetFenceStep(in moveRecoveryInput) (step, dirty bool) { |
| 277 | c, rec, ref := in.Claim, in.Rec, in.TargetFence |
| 278 | if ref == nil || c == nil || rec.Move == nil { |
| 279 | return false, false |
| 280 | } |
| 281 | op, m := c.Op, rec.Move |
| 282 | rb := m.Rollback |
| 283 | if in.TargetFenceConsumed { |
| 284 | return op.Kind == hostclaim.KindRestoring && m.State == provision.MoveRollingBack && rb != nil && rec.Region == m.From && |
| 285 | rb.TargetPhase == provision.RbTargetLost && rb.LossRef == ref.Key && !rb.Dirty, false |
| 286 | } |
| 287 | if !(op.Kind == hostclaim.KindLanding && op.Phase != hostclaim.PhaseCommitted) && op.Kind != hostclaim.KindRestoring { |
| 288 | return false, false |
| 289 | } |
| 290 | if m.State == provision.MoveLanding { |
| 291 | return op.Kind == hostclaim.KindLanding && m.FlippedAt != nil && rec.Region == m.To, false |
| 292 | } |
| 293 | if m.State != provision.MoveRollingBack || rb == nil || rec.Region != m.From { |
| 294 | return false, false |
| 295 | } |
| 296 | switch rb.TargetPhase { |
| 297 | case provision.RbTargetReleasing, provision.RbTargetReturning: |
| 298 | step = true |
| 299 | case provision.RbTargetReleased: |
| 300 | step = rb.Dirty || op.Kind == hostclaim.KindRestoring && op.Phase == hostclaim.PhaseReleasing && op.Exec == op.Intent["target"] |
| 301 | case provision.RbTargetLost: |
| 302 | step = rb.LossRef == ref.Key |
| 303 | } |
| 304 | return step, step && rb.Dirty |
| 305 | } |
| 306 | |
| 307 | // moveDeadlinePassed is the grant's deadline rule: the earlier of the cut and |
| 308 | // landing deadlines (J11, provision.LandingDeadlineOf, the box's own rule) is |
| 309 | // behind now. |
| 310 | func moveDeadlinePassed(m *provision.MoveState, now time.Time) bool { |
| 311 | deadline, _ := provision.LandingDeadlineOf(m) |
| 312 | return deadline != nil && now.After(*deadline) |
| 313 | } |
| 314 | |
| 315 | // owedUnderOp counts the claim's obligations under op id, those match |
| 316 | // accepts when it is set. |
| 317 | func owedUnderOp(c *hostclaim.Claim, id string, match func(hostclaim.Obligation) bool) int { |
| 318 | n := 0 |
| 319 | for _, o := range c.Obligations { |
| 320 | if o.Op == id && (match == nil || match(o)) { |
| 321 | n++ |
| 322 | } |
| 323 | } |
| 324 | return n |
| 325 | } |
| 326 | |
| 327 | func (s *Server) movesNow() time.Time { |
| 328 | if s.movesClock != nil { |
| 329 | return s.movesClock().UTC() |
| 330 | } |
| 331 | return time.Now().UTC() |
| 332 | } |
| 333 | |
| 334 | // movesRecovery is the Recovery.Moves hook (see the file comment). |
| 335 | func (s *Server) movesRecovery(ctx context.Context, g *hostops.MoveRecoveryGrant) error { |
| 336 | a := s.cfg.ClaimAuthority |
| 337 | store := s.cfg.Releases |
| 338 | if a == nil || a.Control == nil || store == nil || g == nil { |
| 339 | return hostops.ErrContract |
| 340 | } |
| 341 | o := g.Observation() |
| 342 | obs, err := hostclaim.Read(ctx, store, o.Host) |
| 343 | if err != nil { |
| 344 | return err |
| 345 | } |
| 346 | if obs.Absent || obs.Claim == nil || obs.Claim.Holder == nil || obs.ETag != o.ClaimETag || obs.Claim.Op.ID != o.OpID { |
| 347 | return nil // moved on since the observation: the next pass observes again |
| 348 | } |
| 349 | c := obs.Claim |
| 350 | r, err := hostops.ReadRecord(ctx, store, c.Holder.Key) |
| 351 | if err != nil { |
| 352 | return err |
| 353 | } |
| 354 | if r.ETag != o.RecordETag { |
| 355 | return nil |
| 356 | } |
| 357 | rec, err := provision.DecodeRecord(r.Body) |
| 358 | if err != nil { |
| 359 | return err |
| 360 | } |
| 361 | now := s.movesNow() |
| 362 | in := moveRecoveryInput{Now: now, Claim: c, Rec: rec} |
| 363 | ours := rec.Move != nil && rec.Move.ID == o.OpID |
| 364 | if c.Op.Kind == hostclaim.KindMoving && c.Op.Phase == hostclaim.PhaseMoving && !ours { |
| 365 | adm, err := hostops.ReadAdmission(ctx, store, o.Account, o.App, o.AppID) |
| 366 | if err != nil { |
| 367 | return err |
| 368 | } |
| 369 | if e, ok := adm.Value.Effects[o.OpID]; ok { |
| 370 | in.Start = &e |
| 371 | } |
| 372 | } |
| 373 | if c.Op.Kind == hostclaim.KindMoving && ours { |
| 374 | if in.Fence, err = s.sourceFence(ctx, c); err != nil { |
| 375 | return err |
| 376 | } |
| 377 | } |
| 378 | if ours && (c.Op.Kind == hostclaim.KindLanding && c.Op.Phase != hostclaim.PhaseCommitted || c.Op.Kind == hostclaim.KindRestoring) { |
| 379 | // Once consumed, the fence is the claim's, never the bucket's (Q8). |
| 380 | if ref, ok := hostclaim.ConsumedMoveTargetFence(c); ok { |
| 381 | in.TargetFence, in.TargetFenceConsumed = &ref, true |
| 382 | } else if in.TargetFence, err = s.bucketFence(ctx, c.Op.Intent["target_enrollment"]); err != nil { |
| 383 | return err |
| 384 | } |
| 385 | } |
| 386 | d := decideMoveRecovery(in) |
| 387 | for _, kind := range d.Pages { |
| 388 | s.pageMove(ctx, kind, o, c, rec, now) |
| 389 | } |
| 390 | switch d.Action { |
| 391 | case moveActResolveStart: |
| 392 | out, err := g.ResolveStart(ctx) |
| 393 | if errors.Is(err, hostops.ErrMoveStartFenceUnproven) { |
| 394 | log.Printf("console: moves: %s: the start of move %s is uncertain and its record has not advanced past it; left", o.Host, o.OpID) |
| 395 | return nil |
| 396 | } |
| 397 | if err == nil { |
| 398 | log.Printf("console: moves: %s: the start of move %s settled %s", o.Host, o.OpID, out) |
| 399 | } |
| 400 | return err |
| 401 | case moveActConvert: |
| 402 | return g.Convert(ctx, *in.Fence) |
| 403 | case moveActAbort: |
| 404 | co, err := hostops.ObserveConsoleMove(ctx, store, o.Account, o.App, o.Host) |
| 405 | if err != nil { |
| 406 | return err |
| 407 | } |
| 408 | if co != o { |
| 409 | return nil |
| 410 | } |
| 411 | if _, err := a.Control.ConsoleMove(ctx, co, hostops.ConsoleMoveAbort); err != nil { |
| 412 | return err |
| 413 | } |
| 414 | log.Printf("console: moves: %s: move %s is still preparing after %s; aborted", o.Host, o.OpID, moves.AbortAfter) |
| 415 | if t, ok := abortTransition(rec); ok { |
| 416 | s.queueMoveLog(o, t, now) |
| 417 | } |
| 418 | return nil |
| 419 | case moveActClaim: |
| 420 | if d.Claim == hostops.RecoveryMoveRelease { |
| 421 | // claim_released is published only from a release that |
| 422 | // happened: queued unconfirmed now, confirmed once the release |
| 423 | // succeeds (a crash between the two is settled by the drainer, |
| 424 | // from the claim). |
| 425 | s.queueMoveLogAs(o, claimTransition(o, rec, "claim_released", "claim-released"), now, false) |
| 426 | if f := s.moveReleaseFault; f != nil { |
| 427 | if err := f(); err != nil { |
| 428 | return err |
| 429 | } |
| 430 | } |
| 431 | } |
| 432 | if err := g.Claim(ctx, d.Claim); err != nil { |
| 433 | return err |
| 434 | } |
| 435 | switch d.Claim { |
| 436 | case hostops.RecoveryMoveRelease: |
| 437 | if err := s.store.ConfirmMoveLog(o.Host, o.OpID, "claim-released"); err != nil { |
| 438 | log.Printf("console: moves: %s: the release of move %s is not confirmed in its log outbox (the drainer settles it from the claim): %v", o.Host, o.OpID, err) |
| 439 | } |
| 440 | case hostops.RecoveryMoveRollback: |
| 441 | s.queueMoveLog(o, claimTransition(o, rec, "claim_rollback", "claim-rollback"), now) |
| 442 | } |
| 443 | return nil |
| 444 | case moveActRecord: |
| 445 | if err := g.Record(ctx, d.Record); err != nil { |
| 446 | return err |
| 447 | } |
| 448 | if t, ok := g.Transition(); ok { |
| 449 | s.queueMoveLog(o, t, now) |
| 450 | } |
| 451 | return nil |
| 452 | case moveActStampLost: |
| 453 | return g.StampLostMoveTargetParked(ctx) |
| 454 | case moveActFence: |
| 455 | if f := s.moveFenceCall; f != nil { |
| 456 | f(*in.TargetFence) |
| 457 | } |
| 458 | out, err := g.ReleaseFencedTarget(ctx, *in.TargetFence) |
| 459 | if out.VerifiedDirty && errors.Is(err, hostops.ErrPending) { |
| 460 | // Only the grant's verified-dirty outcome pages (fix round 1, |
| 461 | // item 1): it is given after the fence verified. Any other |
| 462 | // ErrPending (a withdrawn registration, a spent grant) is not |
| 463 | // evidence of a terminated target. J4, the operator's |
| 464 | // declaration, takes it from here. |
| 465 | s.pageMove(ctx, movePageTargetFencedDirty, o, c, rec, now) |
| 466 | return nil |
| 467 | } |
| 468 | if err != nil { |
| 469 | return err |
| 470 | } |
| 471 | // The step's own writes, from the grant's evidence (fix round 1, |
| 472 | // item 2), never from a later read of the record. |
| 473 | if out.Transition != nil { |
| 474 | s.queueMoveLog(o, *out.Transition, now) |
| 475 | } |
| 476 | if out.ClaimRolledBack { |
| 477 | s.queueMoveLog(o, claimTransition(o, rec, "claim_rollback", "claim-rollback"), now) |
| 478 | } |
| 479 | return nil |
| 480 | case moveActClose: |
| 481 | if !s.moveCloseOverdue(o, d.Record, now) { |
| 482 | return nil |
| 483 | } |
| 484 | if err := g.Record(ctx, d.Record); err != nil { |
| 485 | return err |
| 486 | } |
| 487 | log.Printf("console: moves: %s: move %s closed by the console (%s); the release follows", o.Host, o.OpID, d.Record) |
| 488 | if t, ok := g.Transition(); ok { |
| 489 | s.queueMoveLog(o, t, now) |
| 490 | } |
| 491 | s.pageMove(ctx, movePageCloseOverdue, o, c, rec, now) |
| 492 | return nil |
| 493 | case moveActAbortOverdue: |
| 494 | if s.moveAbortOverdue(o, park.QuietUntil(c.QuietAfter, s.cfg.dbClaimHomeRegion(), park.PlacementRegion(rec.Move.To)), now) { |
| 495 | s.pageMove(ctx, movePageAbortOverdue, o, c, rec, now) |
| 496 | } |
| 497 | return nil |
| 498 | } |
| 499 | return nil |
| 500 | } |
| 501 | |
| 502 | // sourceFence is the moving source's termination fence, when one exists: |
| 503 | // the reference to control/box-fences/<source enrollment>.json and its exact |
| 504 | // bytes. Convert verifies it; nothing here trusts it. |
| 505 | func (s *Server) sourceFence(ctx context.Context, c *hostclaim.Claim) (*hostclaim.FenceRef, error) { |
| 506 | return s.bucketFence(ctx, c.Op.Intent["source_enrollment"]) |
| 507 | } |
| 508 | |
| 509 | // bucketFence is the termination fence of the box enrolled as enrollment, |
| 510 | // when one exists in the bucket: its reference and its exact bytes' digest. |
| 511 | // The grant verifies it; nothing here trusts it. |
| 512 | func (s *Server) bucketFence(ctx context.Context, enrollment string) (*hostclaim.FenceRef, error) { |
| 513 | if enrollment == "" { |
| 514 | return nil, nil |
| 515 | } |
| 516 | key := hostfence.FenceKey(enrollment) |
| 517 | body, _, err := s.cfg.Releases.Get(ctx, key) |
| 518 | if errors.Is(err, os.ErrNotExist) { |
| 519 | return nil, nil |
| 520 | } |
| 521 | if err != nil { |
| 522 | return nil, err |
| 523 | } |
| 524 | sum := sha256.Sum256(body) |
| 525 | return &hostclaim.FenceRef{Enrollment: enrollment, Key: key, SHA256: hex.EncodeToString(sum[:])}, nil |
| 526 | } |
| 527 | |
| 528 | // moveDueSince is when the pass first saw this close due, remembering now |
| 529 | // if it had not. The memory is the process's: a restarted console waits the |
| 530 | // grace again, which only delays the console's close or page. Entries a day |
| 531 | // old are dropped. |
| 532 | func (s *Server) moveDueSince(key string, now time.Time) time.Time { |
| 533 | s.moveCloseMu.Lock() |
| 534 | defer s.moveCloseMu.Unlock() |
| 535 | if s.moveCloseSeen == nil { |
| 536 | s.moveCloseSeen = map[string]time.Time{} |
| 537 | } |
| 538 | for k, at := range s.moveCloseSeen { |
| 539 | if now.Sub(at) > 24*time.Hour { |
| 540 | delete(s.moveCloseSeen, k) |
| 541 | } |
| 542 | } |
| 543 | first, ok := s.moveCloseSeen[key] |
| 544 | if !ok { |
| 545 | s.moveCloseSeen[key] = now |
| 546 | return now |
| 547 | } |
| 548 | return first |
| 549 | } |
| 550 | |
| 551 | // moveCloseOverdue reports whether this close has been due for |
| 552 | // moveCloseGrace; when it has, the memory is cleared for the close. |
| 553 | func (s *Server) moveCloseOverdue(o hostops.ConsoleMoveObservation, action hostops.MoveRecoveryRecordAction, now time.Time) bool { |
| 554 | key := o.Host + "|" + o.OpID + "|" + string(action) |
| 555 | if now.Sub(s.moveDueSince(key, now)) < moveCloseGrace { |
| 556 | return false |
| 557 | } |
| 558 | s.moveCloseMu.Lock() |
| 559 | delete(s.moveCloseSeen, key) |
| 560 | s.moveCloseMu.Unlock() |
| 561 | return true |
| 562 | } |
| 563 | |
| 564 | // moveAbortOverdue reports whether an abort with nothing owed has stayed |
| 565 | // unclosed past its lane's horizon (quiet, the claim's quiet_after for the |
| 566 | // target region, when the claim has one) plus moveCloseGrace, and has been |
| 567 | // seen due for moveCloseGrace itself. The page it leads to is once per move |
| 568 | // (pageMove), so the memory is kept. |
| 569 | func (s *Server) moveAbortOverdue(o hostops.ConsoleMoveObservation, quiet, now time.Time) bool { |
| 570 | since := s.moveDueSince(o.Host+"|"+o.OpID+"|abort", now) |
| 571 | if now.Sub(since) < moveCloseGrace { |
| 572 | return false |
| 573 | } |
| 574 | return quiet.IsZero() || !now.Before(quiet.Add(moveCloseGrace)) |
| 575 | } |
| 576 | |
| 577 | // pageMove sends one page for a finding (its kind, host and move) unless |
| 578 | // the finding was paged before: ever, for a once-per-move page, or within |
| 579 | // the last full hour, for the release deadline. The attempt's time is |
| 580 | // recorded whether or not delivery worked (pages are best effort). |
| 581 | func (s *Server) pageMove(ctx context.Context, kind movePageKind, o hostops.ConsoleMoveObservation, c *hostclaim.Claim, rec provision.Record, now time.Time) { |
| 582 | rule := string(kind) + " " + o.Host + " " + o.OpID |
| 583 | level := alerting.LevelWarning |
| 584 | every := time.Duration(0) // once per move |
| 585 | var subject, body string |
| 586 | switch kind { |
| 587 | case movePageReleaseDeadline: |
| 588 | level, every = alerting.LevelIncident, time.Hour |
| 589 | subject, body = moveWaitingPage(o.Host, o.OpID, rec.Move.To) |
| 590 | case movePagePreparing: |
| 591 | subject, body = movePreparingPageText(o.Host, o.OpID, rec.Move.To) |
| 592 | case movePageOrphan: |
| 593 | level = alerting.LevelIncident |
| 594 | subject, body = moveOrphanPage(o.Host, o.OpID) |
| 595 | case movePageCloseOverdue: |
| 596 | subject, body = moveCloseOverduePage(o.Host, o.OpID) |
| 597 | case movePageAbortOverdue: |
| 598 | subject, body = moveAbortOverduePage(o.Host, o.OpID, rec.Move.To, c.Op.Intent["source"]) |
| 599 | case movePageTargetFencedDirty: |
| 600 | level = alerting.LevelIncident |
| 601 | subject, body = moveTargetFencedDirtyPage(o.Host, o.OpID, c.Op.Intent["target"], moves.RegionText(rec.Move.To), moves.RegionText(rec.Move.From)) |
| 602 | default: |
| 603 | return |
| 604 | } |
| 605 | if s.store == nil { |
| 606 | return |
| 607 | } |
| 608 | last, paged, err := s.store.MovePageAttempt(rule) |
| 609 | if err != nil { |
| 610 | log.Printf("console: moves: %s: the page record for %s: %v", o.Host, rule, err) |
| 611 | return |
| 612 | } |
| 613 | if paged && (every == 0 || now.Sub(last) < every) { |
| 614 | return |
| 615 | } |
| 616 | if err := s.store.SetMovePageAttempt(rule, now); err != nil { |
| 617 | log.Printf("console: moves: %s: record the page %s: %v", o.Host, rule, err) |
| 618 | return |
| 619 | } |
| 620 | if err := alerting.Page(ctx, level, subject, body); err != nil { |
| 621 | log.Printf("console: moves: %s: page %s: %v", o.Host, kind, err) |
| 622 | } |
| 623 | } |
| 624 | |
| 625 | // moveWaitingPage is a rollback waiting past its release deadline (§7.8 |
| 626 | // waiting): the subject (MV-N325) and the body (MV-N326). |
| 627 | func moveWaitingPage(host, id, to string) (subject, body string) { |
| 628 | subject = fmt.Sprintf("carlos move waiting for %s to release: %s", to, host) |
| 629 | body = fmt.Sprintf("The move %s of %s is rolling back, and %s has not released it by its deadline. %s stays offline until a box in %s confirms it has stopped, or that box is declared lost.", |
| 630 | id, host, to, host, to) |
| 631 | return subject, body |
| 632 | } |
| 633 | |
| 634 | // movePreparingPageText is a move preparing for over an hour (§13): the |
| 635 | // subject (MV-N327) and the body (MV-N328). |
| 636 | func movePreparingPageText(host, id, to string) (subject, body string) { |
| 637 | subject = fmt.Sprintf("carlos move preparing for over an hour: %s", host) |
| 638 | body = fmt.Sprintf("The move %s of %s to %s has been preparing for over an hour. It aborts itself six hours after the request if %s is still not ready.", |
| 639 | id, host, to, to) |
| 640 | return subject, body |
| 641 | } |
| 642 | |
| 643 | // moveOrphanPage is a claim held by a move the record does not carry (K3): |
| 644 | // the subject (MV-N329) and the body (MV-N330). |
| 645 | func moveOrphanPage(host, id string) (subject, body string) { |
| 646 | subject = fmt.Sprintf("carlos move without a record: %s", host) |
| 647 | body = fmt.Sprintf("The host claim of %s is held by the move %s, and the instance record carries no move. Nothing releases it on its own. An operator must check the record.", |
| 648 | host, id) |
| 649 | return subject, body |
| 650 | } |
| 651 | |
| 652 | // moveCloseOverduePage is a close the console wrote because no box did: the |
| 653 | // subject (MV-N331) and the body (MV-N332). |
| 654 | func moveCloseOverduePage(host, id string) (subject, body string) { |
| 655 | subject = fmt.Sprintf("carlos move close overdue: %s", host) |
| 656 | body = fmt.Sprintf("The move %s of %s was ready to close for more than 10 minutes and no box closed it. The console has closed it.", id, host) |
| 657 | return subject, body |
| 658 | } |
| 659 | |
| 660 | // moveAbortOverduePage is an abort that owes nothing and that its source has |
| 661 | // not closed (fix round 1, ruling 1): the subject (MV-N333) and the body |
| 662 | // (MV-N334). |
| 663 | func moveAbortOverduePage(host, id, to, box string) (subject, body string) { |
| 664 | subject = fmt.Sprintf("carlos move abort not closed: %s", host) |
| 665 | body = fmt.Sprintf("The abort of the move %s of %s has nothing left to park in %s, and %s has not closed it. %s closes it once it has removed the move's snapshots from its own bucket. Check %s.", |
| 666 | id, host, to, box, box, box) |
| 667 | return subject, body |
| 668 | } |
| 669 | |
| 670 | // moveTargetFencedDirtyPage is a target terminated before it returned the |
| 671 | // writes it made, whose fence the grant refuses (Q8, left for J4): the |
| 672 | // subject (MV-N450) and the body (MV-N451). to and from are as a sentence |
| 673 | // names them (moves.RegionText). |
| 674 | func moveTargetFencedDirtyPage(host, id, box, to, from string) (subject, body string) { |
| 675 | subject = fmt.Sprintf("carlos move target terminated before returning its writes: %s", host) |
| 676 | body = fmt.Sprintf("%s in %s was terminated after it wrote data it had not returned to %s. the move %s of %s cannot finish on its own. run carlos move resolve --host %s --declare-lost %s to move %s back to %s.", |
| 677 | box, to, from, id, host, host, box, host, from) |
| 678 | return subject, body |
| 679 | } |
| 680 | |
| 681 | // The move log of the console's own move writes (Plan 6 Task 3; fix round 3, |
| 682 | // ruling 1): the closes, the landing deadline's rollback, the six-hour abort, |
| 683 | // and the claim's rollback and release. Each entry is named as a box's write |
| 684 | // of the same transition would be (moves.TransitionOf), from the write's own |
| 685 | // evidence (the grant's Transition, or the record the pass acted on), and |
| 686 | // carries the console as its actor; the console has no member sink. |
| 687 | // |
| 688 | // The release's own entry (claim_released) is published only from a release |
| 689 | // that happened (ruling 2): queued unconfirmed before g.Claim and confirmed |
| 690 | // after it succeeds; the drainer settles a row left unconfirmed (a failed |
| 691 | // release, or a crash before the confirm) from the claim. A declared loss of |
| 692 | // a move's target (declared_lost) is the console's too, from either door |
| 693 | // that performs the declaration, in the same two phases (final review I4, |
| 694 | // declareMoveLossLogged); the drainer settles its unconfirmed row from the |
| 695 | // loss the claim records (settleDeclaredLost). |
| 696 | // |
| 697 | // An entry is queued in the console's outbox (move_log_outbox) with its |
| 698 | // exact bytes and its report prefix, and the recovery pass's drainer |
| 699 | // (drainMoveLog) delivers it, once a pass, whatever its move has done since: |
| 700 | // independent of any grant (spent by the time the entry exists) and of the |
| 701 | // claim's release, which never waits for the log. A row whose write fails |
| 702 | // is retried with backoff, indefinitely, and warned of once in the journal |
| 703 | // when it is an hour old. A confirmed row the writer refuses outright is |
| 704 | // held, never deleted: kept, not retried and warned of once, until its |
| 705 | // incarnation is retired or purged (PurgeMoveLogIncarnation). A release of a start never applied is not logged: |
| 706 | // the record never named that move. |
| 707 | |
| 708 | // moveLogWarnAfter is the age at which an undelivered entry is warned of. |
| 709 | const moveLogWarnAfter = time.Hour |
| 710 | |
| 711 | // moveLogDrainBatch bounds one pass's deliveries. |
| 712 | const moveLogDrainBatch = 256 |
| 713 | |
| 714 | // moveLogBackoff is the wait after a row's attempts-th failure: 30 seconds, |
| 715 | // doubling, at most an hour. |
| 716 | func moveLogBackoff(attempts int) time.Duration { |
| 717 | d := 30 * time.Second |
| 718 | for i := 1; i < attempts && d < time.Hour; i++ { |
| 719 | d *= 2 |
| 720 | } |
| 721 | return min(d, time.Hour) |
| 722 | } |
| 723 | |
| 724 | // moveLogEntry is the console's entry for t. |
| 725 | func moveLogEntry(o hostops.ConsoleMoveObservation, t moves.Transition, now time.Time) ([]byte, error) { |
| 726 | return json.Marshal(moves.LogEvent{V: 1, Op: t.Op, Host: o.Host, Event: t.Event, Identity: t.Identity, Actor: "console", At: now.UTC(), Fields: t.Fields}) |
| 727 | } |
| 728 | |
| 729 | // queueMoveLog queues the entry for t, for the drainer. |
| 730 | func (s *Server) queueMoveLog(o hostops.ConsoleMoveObservation, t moves.Transition, now time.Time) { |
| 731 | s.queueMoveLogAs(o, t, now, true) |
| 732 | } |
| 733 | |
| 734 | // queueMoveLogAs queues the entry for t, confirmed or not: the drainer |
| 735 | // delivers a confirmed entry, and settles an unconfirmed one from the claim |
| 736 | // (settleUnconfirmed). The row is bound to the incarnation t's evidence |
| 737 | // carried, which must be the grant's move and instance. |
| 738 | func (s *Server) queueMoveLogAs(o hostops.ConsoleMoveObservation, t moves.Transition, now time.Time, confirmed bool) { |
| 739 | if err := s.queueMoveLogErr(o, t, now, confirmed); err != nil { |
| 740 | log.Printf("console: moves: %s: the log of move %s at %s is lost: %v", o.Host, o.OpID, t.Identity, err) |
| 741 | } |
| 742 | } |
| 743 | |
| 744 | // queueMoveLogErr is queueMoveLogAs, answering whether the row is queued: |
| 745 | // for a caller that must not act unless it is (declareMoveLossLogged). |
| 746 | func (s *Server) queueMoveLogErr(o hostops.ConsoleMoveObservation, t moves.Transition, now time.Time, confirmed bool) error { |
| 747 | if t.Op != o.OpID || t.Incarnation != o.Incarnation { |
| 748 | return fmt.Errorf("the entry names move %s of incarnation %q, not move %s of %q", t.Op, t.Incarnation, o.OpID, o.Incarnation) |
| 749 | } |
| 750 | body, err := moveLogEntry(o, t, now) |
| 751 | if err != nil { |
| 752 | return err |
| 753 | } |
| 754 | return s.store.QueueMoveLog(o.Host, o.OpID, t.Identity, t.Incarnation, body, confirmed, now) |
| 755 | } |
| 756 | |
| 757 | // claimRootKey is the root public key the claim runtime signs with, which |
| 758 | // the move loss challenges and records verify under; nil without the |
| 759 | // runtime. |
| 760 | func (s *Server) claimRootKey() ed25519.PublicKey { |
| 761 | if a := s.cfg.ClaimAuthority; a != nil { |
| 762 | return a.Signer.RootPublicKey() |
| 763 | } |
| 764 | return nil |
| 765 | } |
| 766 | |
| 767 | // confirmMoveLog confirms t's entry once the write it names succeeded. The |
| 768 | // row is queued again, confirmed, in case a pass dropped the unconfirmed one |
| 769 | // in between (settleDeclaredLost drops a row whose loss is not committed |
| 770 | // yet), and then marked confirmed if it was there already. |
| 771 | func (s *Server) confirmMoveLog(o hostops.ConsoleMoveObservation, t moves.Transition, now time.Time) { |
| 772 | s.queueMoveLogAs(o, t, now, true) |
| 773 | if err := s.store.ConfirmMoveLog(o.Host, o.OpID, t.Identity); err != nil { |
| 774 | log.Printf("console: moves: %s: the log of move %s at %s is not confirmed in its log outbox (the drainer settles it): %v", o.Host, o.OpID, t.Identity, err) |
| 775 | } |
| 776 | } |
| 777 | |
| 778 | // declareMoveLossLogged runs one declaration of a move's lost target |
| 779 | // (declare, the configured authority's DeclareMoveLoss) with its move log |
| 780 | // entry, declared_lost (final review I4): queued unconfirmed before the |
| 781 | // declaration, from the record as the door reads it, and confirmed once the |
| 782 | // declaration succeeds. The declaration moves the target on from lost to |
| 783 | // released within the request, so the box's pass may never see it lost; the |
| 784 | // console that performed it is the entry's producer. A record that cannot be |
| 785 | // read, or a row that cannot be queued, refuses the declaration: an |
| 786 | // operator's action fails closed rather than leave no retry for its entry |
| 787 | // (final re-review 1, I4). |
| 788 | func (s *Server) declareMoveLossLogged(ctx context.Context, account, app, host string, sub hostfence.Submission, declare func() error) error { |
| 789 | var ( |
| 790 | o hostops.ConsoleMoveObservation |
| 791 | t moves.Transition |
| 792 | logged bool |
| 793 | ) |
| 794 | rec, err := provision.GetRecord(ctx, s.cfg.Releases, account, app, host) |
| 795 | if err != nil { |
| 796 | // Fail closed (final re-review 1, I4): a declaration whose entry |
| 797 | // cannot be queued is not made. |
| 798 | return fmt.Errorf("moves: the declared loss cannot be queued in the move log: the record cannot be read: %w", err) |
| 799 | } |
| 800 | // Only a declaration whose signed consequence is the loss of this move's |
| 801 | // target is declared_lost; a destroyed-local-only one changes no move |
| 802 | // state and logs nothing (final re-review 1, N1). |
| 803 | if op, inc, ok := hostops.DeclaresMoveTargetLoss(s.claimRootKey(), sub); ok && rec.Move != nil && op == rec.Move.ID && inc == rec.Move.Incarnation { |
| 804 | if t, logged = moves.DeclaredLost(rec.Move); logged { |
| 805 | o = hostops.ConsoleMoveObservation{Host: host, OpID: rec.Move.ID, Incarnation: rec.Move.Incarnation} |
| 806 | if err := s.queueMoveLogErr(o, t, s.movesNow(), false); err != nil { |
| 807 | return fmt.Errorf("moves: the declared loss cannot be queued in the move log: %w", err) |
| 808 | } |
| 809 | } |
| 810 | } |
| 811 | if err := declare(); err != nil { |
| 812 | return err |
| 813 | } |
| 814 | if logged { |
| 815 | s.confirmMoveLog(o, t, s.movesNow()) |
| 816 | } |
| 817 | return nil |
| 818 | } |
| 819 | |
| 820 | // drainMoveLog is the Recovery.MoveLogs hook: every due row of the outbox, |
| 821 | // delivered through the pass's writer. |
| 822 | func (s *Server) drainMoveLog(ctx context.Context, lw *hostops.MoveLogWriter) error { |
| 823 | now := s.movesNow() |
| 824 | rows, err := s.store.MoveLogDue(now, moveLogDrainBatch) |
| 825 | if err != nil { |
| 826 | return fmt.Errorf("moves: the log outbox: %w", err) |
| 827 | } |
| 828 | for _, r := range rows { |
| 829 | if err := ctx.Err(); err != nil { |
| 830 | return err |
| 831 | } |
| 832 | if !r.Confirmed { |
| 833 | deliver, wait := s.settleUnconfirmed(ctx, r) |
| 834 | if wait != nil { |
| 835 | s.retryMoveLog(r, now, wait) |
| 836 | } |
| 837 | if !deliver { |
| 838 | continue |
| 839 | } |
| 840 | } |
| 841 | s.deliverMoveLog(ctx, lw, r, now) |
| 842 | } |
| 843 | return nil |
| 844 | } |
| 845 | |
| 846 | // settleUnconfirmed settles a row queued for a release that was not yet |
| 847 | // confirmed, from the host's claim: released for the row's move, it is |
| 848 | // confirmed (deliver); still the move's, or the claim unreadable, it waits |
| 849 | // (wait says why, and it takes a failed delivery's backoff and warning, so |
| 850 | // it rotates out of the batch); anything else, it is dropped with a journal |
| 851 | // line. |
| 852 | func (s *Server) settleUnconfirmed(ctx context.Context, r MoveLogPendingEntry) (deliver bool, wait error) { |
| 853 | if r.Name == moves.DeclaredLostIdentity { |
| 854 | return s.settleDeclaredLost(ctx, r) |
| 855 | } |
| 856 | o, err := hostclaim.Read(ctx, s.cfg.Releases, r.Host) |
| 857 | if err != nil { |
| 858 | return false, fmt.Errorf("unconfirmed, and the claim cannot be read: %w", err) |
| 859 | } |
| 860 | switch { |
| 861 | case !o.Absent && o.Claim != nil && hostclaim.RequireReleasedMove(r.Op)(o.Claim) == nil: |
| 862 | if err := s.store.ConfirmMoveLog(r.Host, r.Op, r.Name); err != nil { |
| 863 | return false, fmt.Errorf("unconfirmed: %w", err) |
| 864 | } |
| 865 | return true, nil |
| 866 | case !o.Absent && o.Claim != nil && o.Claim.Op.ID == r.Op: |
| 867 | return false, errors.New("unconfirmed: the claim still holds the move") |
| 868 | } |
| 869 | log.Printf("console: moves: %s: the log of move %s at %s was never confirmed and the claim no longer holds the move; dropped", r.Host, r.Op, r.Name) |
| 870 | if err := s.store.SettleMoveLog(r.Host, r.Op, r.Name); err != nil { |
| 871 | log.Printf("console: moves: %s: the log outbox of move %s: %v", r.Host, r.Op, err) |
| 872 | } |
| 873 | return false, nil |
| 874 | } |
| 875 | |
| 876 | // settleDeclaredLost settles an unconfirmed declared_lost row (final review |
| 877 | // I4; final re-review 1) from the claim. A committed loss of the move's |
| 878 | // target, in the claim's loss_refs (which the declaration's claim CAS writes |
| 879 | // as it commits, and nothing removes), confirms the row (deliver). While the |
| 880 | // move can still be declared lost (the claim's op is still the move, not |
| 881 | // released to serving) the row is kept, however long, with the failed |
| 882 | // delivery's backoff and its one warning. It is dropped only once the claim |
| 883 | // shows the move closed or released with no such loss, or the instance's |
| 884 | // incarnation gone (no claim, or another holder); the incarnation's purge |
| 885 | // deletes it too (PurgeMoveLogIncarnation). The drop deletes only a row |
| 886 | // still unconfirmed, so a declaration that confirmed its row after the claim |
| 887 | // was read here keeps it. A claim or loss record that cannot be read waits. |
| 888 | func (s *Server) settleDeclaredLost(ctx context.Context, r MoveLogPendingEntry) (deliver bool, wait error) { |
| 889 | o, err := hostclaim.Read(ctx, s.cfg.Releases, r.Host) |
| 890 | if err != nil { |
| 891 | return false, fmt.Errorf("unconfirmed, and the claim cannot be read: %w", err) |
| 892 | } |
| 893 | if f := s.moveLogSettleHook; f != nil { |
| 894 | f() |
| 895 | } |
| 896 | drop := func(why string) (bool, error) { |
| 897 | log.Printf("console: moves: %s: the log of move %s at %s was never confirmed and %s; dropped", r.Host, r.Op, r.Name, why) |
| 898 | if err := s.store.DropUnconfirmedMoveLog(r.Host, r.Op, r.Name); err != nil { |
| 899 | log.Printf("console: moves: %s: the log outbox of move %s: %v", r.Host, r.Op, err) |
| 900 | } |
| 901 | return false, nil |
| 902 | } |
| 903 | if o.Absent || o.Claim == nil || o.Claim.Holder == nil || o.Claim.Holder.Incarnation != r.Incarnation { |
| 904 | return drop("the claim no longer holds the instance it was queued for") |
| 905 | } |
| 906 | if len(o.Claim.LossRefs) > 0 { |
| 907 | pub := s.claimRootKey() |
| 908 | if len(pub) != ed25519.PublicKeySize { |
| 909 | return false, errors.New("unconfirmed, and there is no key to read the claim's loss records") |
| 910 | } |
| 911 | for _, id := range o.Claim.LossRefs { |
| 912 | l, err := hostclaim.ReadLossRecord(ctx, s.cfg.Releases, pub, id) |
| 913 | if errors.Is(err, hostclaim.ErrLossRecordAbsent) || errors.Is(err, hostclaim.ErrLossRecord) { |
| 914 | continue |
| 915 | } |
| 916 | if err != nil { |
| 917 | return false, fmt.Errorf("unconfirmed, and a loss record cannot be read: %w", err) |
| 918 | } |
| 919 | // Only a loss of the move's target, signed as such, is the |
| 920 | // row's evidence: a destroyed-local-only loss of the same op is |
| 921 | // not (final re-review 1, N1). |
| 922 | op, inc, target := hostops.MoveTargetLossOf(l.Record) |
| 923 | if !target || op != r.Op || inc != r.Incarnation || l.Record.Host != r.Host || l.Record.OpID != r.Op { |
| 924 | continue |
| 925 | } |
| 926 | if err := s.store.ConfirmMoveLog(r.Host, r.Op, r.Name); err != nil { |
| 927 | return false, fmt.Errorf("unconfirmed: %w", err) |
| 928 | } |
| 929 | return true, nil |
| 930 | } |
| 931 | } |
| 932 | if o.Claim.Op.ID == r.Op && o.Claim.Op.Kind != hostclaim.KindServing { |
| 933 | return false, errors.New("unconfirmed: no loss of the move's target has committed, and the move can still be declared lost") |
| 934 | } |
| 935 | return drop("the claim shows the move closed or released with no loss of its target") |
| 936 | } |
| 937 | |
| 938 | // retryMoveLog moves a row's next attempt on after one that did not settle |
| 939 | // it (why), and warns of it once in the journal when it is an hour old. |
| 940 | func (s *Server) retryMoveLog(r MoveLogPendingEntry, now time.Time, why error) { |
| 941 | attempts, warned := r.Attempts+1, r.Warned |
| 942 | if !warned && now.Sub(r.QueuedAt) >= moveLogWarnAfter { |
| 943 | log.Printf("console: moves: warning: %s: the log of move %s at %s has been unwritten for over an hour: %v", r.Host, r.Op, r.Name, why) |
| 944 | warned = true |
| 945 | } |
| 946 | if err := s.store.RetryMoveLog(r.Host, r.Op, r.Name, attempts, now.Add(moveLogBackoff(attempts)), warned); err != nil { |
| 947 | log.Printf("console: moves: %s: the log outbox of move %s: %v", r.Host, r.Op, err) |
| 948 | } |
| 949 | } |
| 950 | |
| 951 | // deliverMoveLog writes one row, and settles it or schedules its retry. |
| 952 | func (s *Server) deliverMoveLog(ctx context.Context, lw *hostops.MoveLogWriter, r MoveLogPendingEntry, now time.Time) { |
| 953 | settle := func() { |
| 954 | if err := s.store.SettleMoveLog(r.Host, r.Op, r.Name); err != nil { |
| 955 | log.Printf("console: moves: %s: the log outbox of move %s: %v", r.Host, r.Op, err) |
| 956 | } |
| 957 | } |
| 958 | _, err := lw.WriteMoveLog(ctx, hostops.MoveLogEntry{Host: r.Host, Op: r.Op, Incarnation: r.Incarnation, Name: r.Name, Body: r.Body}) |
| 959 | switch { |
| 960 | case err == nil: |
| 961 | settle() |
| 962 | case errors.Is(err, hostops.ErrMoveLogTaken): |
| 963 | log.Printf("console: moves: %s: the log of move %s at %s was written by another writer first", r.Host, r.Op, r.Name) |
| 964 | settle() |
| 965 | case errors.Is(err, hostops.ErrIdentity): |
| 966 | // The writer refuses it (its claim's incarnation or record no |
| 967 | // longer vouches for it: a later move's close, a recreation, a |
| 968 | // retirement outside the console's door). The row is never deleted |
| 969 | // for that: it is held, its bytes kept and no longer retried, until |
| 970 | // its incarnation's purge (final fix, ruling 1). |
| 971 | log.Printf("console: moves: warning: %s: the log of move %s at %s is held: the writer refuses it (%v); its entry is kept until its incarnation is purged", r.Host, r.Op, r.Name, err) |
| 972 | if herr := s.store.HoldMoveLog(r.Host, r.Op, r.Name); herr != nil { |
| 973 | log.Printf("console: moves: %s: the log outbox of move %s: %v", r.Host, r.Op, herr) |
| 974 | } |
| 975 | default: |
| 976 | s.retryMoveLog(r, now, err) |
| 977 | } |
| 978 | } |
| 979 | |
| 980 | // abortTransition is the six-hour abort's entry: the record the pass acted |
| 981 | // on, as the abort leaves it (aborting). |
| 982 | func abortTransition(rec provision.Record) (moves.Transition, bool) { |
| 983 | if rec.Move == nil { |
| 984 | return moves.Transition{}, false |
| 985 | } |
| 986 | after, m := rec, *rec.Move |
| 987 | m.State = provision.MoveAborting |
| 988 | after.Move = &m |
| 989 | return moves.TransitionOf(rec, after) |
| 990 | } |
| 991 | |
| 992 | // claimTransition is the entry for a claim write of the console's: the move's |
| 993 | // regions and incarnation from the record the pass acted on (a closed |
| 994 | // move's, from the grant's observation of the same instance). |
| 995 | func claimTransition(o hostops.ConsoleMoveObservation, rec provision.Record, event, identity string) moves.Transition { |
| 996 | t := moves.Transition{Op: o.OpID, Event: event, Identity: identity, Incarnation: o.Incarnation} |
| 997 | if m := rec.Move; m != nil { |
| 998 | t.Incarnation = m.Incarnation |
| 999 | t.Fields = map[string]string{"from": m.From, "to": m.To} |
| 1000 | } |
| 1001 | return t |
| 1002 | } |
| 1003 | |
amadan