platform/app: stream SAT job output live and kick blackbox on job completion
A crash mid-command (e.g. the nvbandwidth reboot) previously lost that job's entire output: streamExecOutput only buffered stdout/stderr in memory and the job's log file was written once, after the process exited. It now also streams each line straight to that file as it arrives, so whatever printed before a crash survives. Root filesystem here is a tmpfs overlay (toram boot), so the only real persistence boundary is blackbox's mirror to removable media, not the local write itself. platform.SetJobBoundaryHook lets app wire a touch of a small kick-file after each job's output is written; blackboxWorker now polls that file's mtime alongside its normal adaptive timer and syncs immediately on a kick instead of waiting out the current flush period (up to 30s).
This commit is contained in:
Mikhail Chusavitin
@@ -161,19 +161,25 @@ type runtimeChecker interface {
|
||||
CaptureTechnicalDump(baseDir string) error
|
||||
}
|
||||
|
||||
func New(platform *platform.System) *App {
|
||||
func New(sys *platform.System) *App {
|
||||
a := &App{
|
||||
network: platform,
|
||||
services: platform,
|
||||
exports: platform,
|
||||
tools: platform,
|
||||
sat: platform,
|
||||
runtime: platform,
|
||||
installer: platform,
|
||||
network: sys,
|
||||
services: sys,
|
||||
exports: sys,
|
||||
tools: sys,
|
||||
sat: sys,
|
||||
runtime: sys,
|
||||
installer: sys,
|
||||
}
|
||||
if db, err := OpenComponentStatusDB(DefaultExportDir + "/component-status.json"); err == nil {
|
||||
a.StatusDB = db
|
||||
}
|
||||
// Let any running blackbox worker know promptly when a SAT job finishes,
|
||||
// instead of waiting out its own adaptive flush period — see
|
||||
// requestBlackboxSync/blackboxWorker.run in blackbox.go.
|
||||
platform.SetJobBoundaryHook(func(string) {
|
||||
requestBlackboxSync(DefaultExportDir)
|
||||
})
|
||||
return a
|
||||
}
|
||||
|
||||
|
||||
@@ -26,8 +26,43 @@ const (
|
||||
blackboxMinFlushPeriod = 1 * time.Second
|
||||
blackboxMaxFlushPeriod = 30 * time.Second
|
||||
blackboxRecoveryFastCount = 5
|
||||
|
||||
// blackboxKickFileName is a marker under exportDir that SAT job
|
||||
// execution touches after each job finishes (see platform.SetJobBoundaryHook
|
||||
// wiring in New()). Workers poll its mtime so a just-finished job's
|
||||
// output reaches removable media promptly instead of waiting out
|
||||
// whatever the current adaptive flush period happens to be.
|
||||
blackboxKickFileName = ".blackbox-kick"
|
||||
)
|
||||
|
||||
// blackboxKickPollInterval is how often an idle worker checks the kick file
|
||||
// for a pending out-of-band sync request. A package var (not a const) so
|
||||
// tests can shrink it instead of waiting out the real interval.
|
||||
var blackboxKickPollInterval = 250 * time.Millisecond
|
||||
|
||||
// requestBlackboxSync touches the kick file under exportDir, signalling any
|
||||
// running blackbox worker to sync on its next poll instead of waiting out
|
||||
// its current flush period. Best-effort: a failure here just means the next
|
||||
// scheduled sync picks up the data instead of an early one.
|
||||
func requestBlackboxSync(exportDir string) {
|
||||
path := filepath.Join(exportDir, blackboxKickFileName)
|
||||
now := blackboxNow()
|
||||
if err := os.Chtimes(path, now, now); err == nil {
|
||||
return
|
||||
}
|
||||
_ = os.WriteFile(path, []byte(now.Format(time.RFC3339Nano)+"\n"), 0644)
|
||||
}
|
||||
|
||||
// blackboxKickModTime returns the kick file's mtime, or the zero Time if it
|
||||
// doesn't exist yet (nothing has requested a sync since boot).
|
||||
func blackboxKickModTime(exportDir string) time.Time {
|
||||
info, err := os.Stat(filepath.Join(exportDir, blackboxKickFileName))
|
||||
if err != nil {
|
||||
return time.Time{}
|
||||
}
|
||||
return info.ModTime()
|
||||
}
|
||||
|
||||
var DefaultBlackboxStatePath = DefaultExportDir + "/blackbox-state.json"
|
||||
|
||||
var (
|
||||
@@ -96,8 +131,14 @@ type blackboxWorker struct {
|
||||
flushPeriod time.Duration
|
||||
lastError string
|
||||
fastCycles int
|
||||
lastKickSeen time.Time
|
||||
stopCh chan struct{}
|
||||
stoppedCh chan struct{}
|
||||
|
||||
// syncCycleFunc defaults to w.syncCycle; overridable in tests so run()'s
|
||||
// wait/wake-on-kick logic can be exercised without a real removable-media
|
||||
// mount and copy.
|
||||
syncCycleFunc func() error
|
||||
}
|
||||
|
||||
func RunBlackbox(ctx context.Context, exportDir, statePath string, system *platform.System) error {
|
||||
@@ -309,7 +350,7 @@ func (rt *blackboxRuntime) discoverMarkedTargets() ([]discoveredBlackboxTarget,
|
||||
}
|
||||
|
||||
func newBlackboxWorker(rt *blackboxRuntime, found discoveredBlackboxTarget) *blackboxWorker {
|
||||
return &blackboxWorker{
|
||||
w := &blackboxWorker{
|
||||
runtime: rt,
|
||||
enrollmentID: found.marker.EnrollmentID,
|
||||
target: found.target,
|
||||
@@ -319,24 +360,39 @@ func newBlackboxWorker(rt *blackboxRuntime, found discoveredBlackboxTarget) *bla
|
||||
stopCh: make(chan struct{}),
|
||||
stoppedCh: make(chan struct{}),
|
||||
}
|
||||
w.syncCycleFunc = w.syncCycle
|
||||
return w
|
||||
}
|
||||
|
||||
func (w *blackboxWorker) run() {
|
||||
defer close(w.stoppedCh)
|
||||
kickPoll := time.NewTicker(blackboxKickPollInterval)
|
||||
defer kickPoll.Stop()
|
||||
|
||||
for {
|
||||
start := time.Now()
|
||||
err := w.syncCycle()
|
||||
err := w.syncCycleFunc()
|
||||
duration := time.Since(start)
|
||||
w.finishCycle(duration, err)
|
||||
w.lastKickSeen = blackboxKickModTime(w.runtime.exportDir)
|
||||
|
||||
wait := w.currentFlushPeriod()
|
||||
timer := time.NewTimer(wait)
|
||||
select {
|
||||
case <-w.stopCh:
|
||||
timer.Stop()
|
||||
w.cleanup()
|
||||
return
|
||||
case <-timer.C:
|
||||
waitLoop:
|
||||
for {
|
||||
select {
|
||||
case <-w.stopCh:
|
||||
timer.Stop()
|
||||
w.cleanup()
|
||||
return
|
||||
case <-timer.C:
|
||||
break waitLoop
|
||||
case <-kickPoll.C:
|
||||
if mtime := blackboxKickModTime(w.runtime.exportDir); mtime.After(w.lastKickSeen) {
|
||||
timer.Stop()
|
||||
break waitLoop
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -0,0 +1,136 @@
|
||||
package app
|
||||
|
||||
import (
|
||||
"path/filepath"
|
||||
"sync"
|
||||
"sync/atomic"
|
||||
"testing"
|
||||
"time"
|
||||
)
|
||||
|
||||
func TestRequestBlackboxSyncUpdatesKickModTime(t *testing.T) {
|
||||
dir := t.TempDir()
|
||||
|
||||
before := blackboxKickModTime(dir)
|
||||
if !before.IsZero() {
|
||||
t.Fatalf("blackboxKickModTime before any request = %v, want zero", before)
|
||||
}
|
||||
|
||||
requestBlackboxSync(dir)
|
||||
first := blackboxKickModTime(dir)
|
||||
if first.IsZero() {
|
||||
t.Fatalf("blackboxKickModTime after request is still zero")
|
||||
}
|
||||
|
||||
time.Sleep(5 * time.Millisecond)
|
||||
requestBlackboxSync(dir)
|
||||
second := blackboxKickModTime(dir)
|
||||
if !second.After(first) {
|
||||
t.Fatalf("second kick mtime %v did not advance past first %v", second, first)
|
||||
}
|
||||
}
|
||||
|
||||
func newTestBlackboxWorker(t *testing.T, exportDir string) (*blackboxWorker, *int32) {
|
||||
t.Helper()
|
||||
rt := &blackboxRuntime{
|
||||
exportDir: exportDir,
|
||||
statePath: filepath.Join(t.TempDir(), "blackbox-state.json"),
|
||||
bootFolder: "boot-folder",
|
||||
workers: make(map[string]*blackboxWorker),
|
||||
}
|
||||
w := &blackboxWorker{
|
||||
runtime: rt,
|
||||
flushPeriod: blackboxMinFlushPeriod,
|
||||
status: "running",
|
||||
stopCh: make(chan struct{}),
|
||||
stoppedCh: make(chan struct{}),
|
||||
}
|
||||
var calls int32
|
||||
w.syncCycleFunc = func() error {
|
||||
atomic.AddInt32(&calls, 1)
|
||||
return nil
|
||||
}
|
||||
return w, &calls
|
||||
}
|
||||
|
||||
func TestBlackboxWorkerWakesEarlyOnKick(t *testing.T) {
|
||||
exportDir := t.TempDir()
|
||||
old := blackboxKickPollInterval
|
||||
blackboxKickPollInterval = 5 * time.Millisecond
|
||||
t.Cleanup(func() { blackboxKickPollInterval = old })
|
||||
|
||||
w, calls := newTestBlackboxWorker(t, exportDir)
|
||||
// A long flush period: without the kick mechanism, a second sync
|
||||
// wouldn't happen within the test's timeout.
|
||||
w.flushPeriod = 10 * time.Second
|
||||
|
||||
var wg sync.WaitGroup
|
||||
wg.Add(1)
|
||||
go func() {
|
||||
defer wg.Done()
|
||||
w.run()
|
||||
}()
|
||||
|
||||
// Let the first (immediate) cycle happen.
|
||||
deadline := time.After(2 * time.Second)
|
||||
for atomic.LoadInt32(calls) < 1 {
|
||||
select {
|
||||
case <-deadline:
|
||||
t.Fatal("timed out waiting for first sync cycle")
|
||||
case <-time.After(time.Millisecond):
|
||||
}
|
||||
}
|
||||
|
||||
// Keep requesting a sync until a second cycle happens. A single kick can
|
||||
// legitimately land in the brief window where the worker is still
|
||||
// recording its post-cycle lastKickSeen baseline and get folded into it
|
||||
// harmlessly (the point being tested — that *a* kick wakes the worker
|
||||
// well before the 10s flush period — still holds as long as one of these
|
||||
// repeated kicks lands after that baseline is recorded).
|
||||
deadline = time.After(2 * time.Second)
|
||||
for atomic.LoadInt32(calls) < 2 {
|
||||
requestBlackboxSync(exportDir)
|
||||
select {
|
||||
case <-deadline:
|
||||
t.Fatalf("timed out waiting for kick-triggered sync cycle; calls=%d", atomic.LoadInt32(calls))
|
||||
case <-time.After(5 * time.Millisecond):
|
||||
}
|
||||
}
|
||||
|
||||
w.stop()
|
||||
wg.Wait()
|
||||
}
|
||||
|
||||
func TestBlackboxWorkerStopsCleanly(t *testing.T) {
|
||||
exportDir := t.TempDir()
|
||||
w, calls := newTestBlackboxWorker(t, exportDir)
|
||||
w.flushPeriod = time.Hour
|
||||
|
||||
var wg sync.WaitGroup
|
||||
wg.Add(1)
|
||||
go func() {
|
||||
defer wg.Done()
|
||||
w.run()
|
||||
}()
|
||||
|
||||
deadline := time.After(2 * time.Second)
|
||||
for atomic.LoadInt32(calls) < 1 {
|
||||
select {
|
||||
case <-deadline:
|
||||
t.Fatal("timed out waiting for first sync cycle")
|
||||
case <-time.After(time.Millisecond):
|
||||
}
|
||||
}
|
||||
|
||||
done := make(chan struct{})
|
||||
go func() {
|
||||
w.stop()
|
||||
close(done)
|
||||
}()
|
||||
select {
|
||||
case <-done:
|
||||
case <-time.After(2 * time.Second):
|
||||
t.Fatal("worker.stop() did not return in time")
|
||||
}
|
||||
wg.Wait()
|
||||
}
|
||||
Reference in New Issue
Block a user