lifecycle：被逼停的關機走 BeginFailure；修好 kit/logging 會過期的測試

go/README.md

@@ -62,6 +62,21 @@ sd.Step("drain connections", drain())
 sd.Done()
 ```
 
+**關機分兩種，層級不同。** `BeginShutdown` 是**有秩序的停止**（訊號、操作者要求），
+announce 走 `info`——跑在 `warn` 的部署看不到它，那是刻意的：例行重啟不該每次都喊。
+
+被某件事**逼停**的用 `BeginFailure`，它把觸發的 error 寫成一筆 `error`：
+
+```go
+sd := lifecycle.BeginFailure(logger, "listener failed", err, "addr", addr)
+sd.Step("database", db.Close())
+sd.Done()      // 不會說 "stopped cleanly"——行程是死於某件事的
+```
+
+差別只在層級，而那正是它獨立成一個函式的理由：最需要這筆紀錄的部署就是跑在
+`warn` 的那些，而在那裡，一行 `info` 會被丟掉，行程就這麼消失、什麼都沒留下。
+`err` 傳 `nil` 代表沒有東西逼停它，等同 `BeginShutdown`。
+
 訊號等待也在這裡：
 
 ```go

go/kit/lifecycle/lifecycle_test.go

@@ -106,3 +106,127 @@ func TestUptimeRunsFromBeforeMain(t *testing.T) {
 		t.Fatal("uptime must be measured from process start, not from first use")
 	}
 }
+
+// readLog returns everything the service wrote, so a test can assert on what a
+// given level actually let through.
+func readLog(t *testing.T, path string) string {
+	t.Helper()
+	written, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatal(err)
+	}
+	return string(written)
+}
+
+// levelLogger writes to path at the given level, so a test can assert what a
+// deployment running at that level would actually have on disk. The whole
+// point of BeginFailure is a difference that only exists above info.
+func levelLogger(t *testing.T, path, level string) *logging.Logger {
+	t.Helper()
+	o := logging.Defaults()
+	o.Level = level
+	o.File = path
+	o.Console = io.Discard
+	log, err := logging.New(o)
+	if err != nil {
+		t.Fatal(err)
+	}
+	return log
+}
+
+// A deployment at warn is the one that most needs to know its listener died,
+// and it is exactly the one an info announcement is invisible to. Before
+// BeginFailure existed, every service passed the triggering error as a field on
+// BeginShutdown's info line, so a process that could not bind its port
+// disappeared having written nothing at all.
+func TestFailureIsAudibleAtWarn(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "svc.log")
+	log := levelLogger(t, path, logging.LevelWarn)
+
+	down := lifecycle.BeginFailure(log, "listener failed", os.ErrPermission,
+		"listener", "public", "addr", "127.0.0.1:26700")
+	down.Step("database", nil)
+	down.Done()
+	if err := log.Close(); err != nil {
+		t.Fatal(err)
+	}
+
+	out := readLog(t, path)
+	if !strings.Contains(out, "level=ERROR") || !strings.Contains(out, "shutting down") {
+		t.Errorf("the cause was not written at error:\n%s", out)
+	}
+	for _, want := range []string{
+		`reason="listener failed"`, "permission denied", "listener=public", "addr=127.0.0.1:26700",
+	} {
+		if !strings.Contains(out, want) {
+			t.Errorf("the cause line is missing %s:\n%s", want, out)
+		}
+	}
+	// Tearing down neatly after a listener died is not stopping cleanly, and at
+	// warn that summary would otherwise be the only line to survive.
+	if strings.Contains(out, "stopped cleanly") {
+		t.Errorf("a forced shutdown reported itself as clean:\n%s", out)
+	}
+	if !strings.Contains(out, "stopped after a failure") {
+		t.Errorf("no summary survived at warn:\n%s", out)
+	}
+	// The successful step stays debug: this is the half the spec used to get
+	// wrong in the other direction.
+	if strings.Contains(out, "step=database") {
+		t.Errorf("a successful step was written above debug:\n%s", out)
+	}
+}
+
+// The counterpart of the above, and the half the ruling deliberately left
+// alone: an orderly stop is normal operation, so warn drops it entirely.
+func TestOrderlyShutdownStaysSilentAtWarn(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "svc.log")
+	log := levelLogger(t, path, logging.LevelWarn)
+
+	down := lifecycle.BeginShutdown(log, "signal", "signal", "terminated")
+	down.Step("control listener", nil)
+	down.Done()
+	if err := log.Close(); err != nil {
+		t.Fatal(err)
+	}
+
+	if out := readLog(t, path); strings.TrimSpace(out) != "" {
+		t.Errorf("an orderly shutdown must not be audible at warn, got:\n%s", out)
+	}
+}
+
+// A failed step still outranks everything: it is how state gets left behind.
+func TestFailedStepIsErrorEvenAfterAnOrderlyStart(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "svc.log")
+	log := levelLogger(t, path, logging.LevelWarn)
+
+	down := lifecycle.BeginShutdown(log, "signal", "signal", "terminated")
+	down.Step("release leases", os.ErrDeadlineExceeded, "remaining", 2)
+	down.Done()
+	if err := log.Close(); err != nil {
+		t.Fatal(err)
+	}
+
+	out := readLog(t, path)
+	if !strings.Contains(out, "level=ERROR") || !strings.Contains(out, "step=\"release leases\"") {
+		t.Errorf("a failed step must be error even at warn:\n%s", out)
+	}
+	if !strings.Contains(out, "failed_steps=1") {
+		t.Errorf("the summary lost the failure count:\n%s", out)
+	}
+}
+
+// nil means nothing forced this, so it is an orderly shutdown and is announced
+// as one — callers with a single code path must not accidentally shout.
+func TestBeginFailureWithoutAnErrorIsOrderly(t *testing.T) {
+	path := filepath.Join(t.TempDir(), "svc.log")
+	log := levelLogger(t, path, logging.LevelWarn)
+
+	lifecycle.BeginFailure(log, "signal", nil, "signal", "terminated").Done()
+	if err := log.Close(); err != nil {
+		t.Fatal(err)
+	}
+	if out := readLog(t, path); strings.TrimSpace(out) != "" {
+		t.Errorf("a nil cause must behave like BeginShutdown, got:\n%s", out)
+	}
+}

go/kit/lifecycle/shutdown.go

@@ -16,15 +16,24 @@ type Shutdown struct {
 	log    Logger
 	begun  time.Time
 	reason string
+	// caused records that this shutdown was triggered by a failure rather than
+	// by a signal, so Done does not call the result clean.
+	caused bool
 
 	mu     sync.Mutex
 	steps  int
 	failed int
 }
 
-// BeginShutdown announces the shutdown and starts recording it. reason is the
-// cause in a few words — "signal", "listener failed", "operator requested"
-// — and attrs carry the context that makes it actionable.
+// BeginShutdown announces an orderly shutdown and starts recording it. reason
+// is the cause in a few words — "signal", "operator requested" — and attrs
+// carry the context that makes it actionable.
+//
+// The announcement is info, and a deployment running at warn will not see it.
+// That is deliberate: an orderly stop is part of normal operation, and paying
+// for it at warn would mean every routine restart shouts. A shutdown that was
+// *caused by something going wrong* is not this function's job — use
+// BeginFailure, which is audible at warn.
 func BeginShutdown(log Logger, reason string, attrs ...any) *Shutdown {
 	s := &Shutdown{log: log, begun: time.Now(), reason: reason}
 	log.Info("shutting down", append([]any{
@@ -34,6 +43,33 @@ func BeginShutdown(log Logger, reason string, attrs ...any) *Shutdown {
 	return s
 }
 
+// BeginFailure announces a shutdown that something forced — a listener that
+// could not bind, a dependency that will not answer — and records it the same
+// way BeginShutdown does from there on.
+//
+// The difference is the level, and it is the whole point of having two
+// functions. The triggering error goes out at error, not as a field on an info
+// line, because the deployments that most need this record are the ones running
+// at warn: there, an info announcement is dropped and the process disappears
+// having written nothing at all. Done() will not report "stopped cleanly"
+// afterwards either — the process died of something, and a summary saying
+// otherwise is worse than no summary.
+//
+// A nil err means nothing forced this, so it is an orderly shutdown and is
+// announced as one.
+func BeginFailure(log Logger, reason string, err error, attrs ...any) *Shutdown {
+	if err == nil {
+		return BeginShutdown(log, reason, attrs...)
+	}
+	s := &Shutdown{log: log, begun: time.Now(), reason: reason, caused: true}
+	log.Error("shutting down", append([]any{
+		"reason", reason,
+		"error", err,
+		"uptime", Uptime().Round(time.Millisecond).String(),
+	}, attrs...)...)
+	return s
+}
+
 // Step records the outcome of one teardown step. A failure is logged with its
 // error and whatever context the caller passes; a success is debug-level detail
 // nobody needs unless they are already looking.
@@ -60,6 +96,11 @@ func (s *Shutdown) Step(name string, err error, attrs ...any) {
 // a shutdown with a failed step is how state gets left behind — a lease not
 // released, a connection not closed, a game not handed over — and that is the
 // thing someone will be looking for later.
+//
+// A shutdown opened by BeginFailure is also warn even when every step
+// succeeded: tearing down neatly after a listener died is not stopping
+// cleanly, and at warn that summary would otherwise be the only line the
+// deployment could have seen.
 func (s *Shutdown) Done(attrs ...any) {
 	s.mu.Lock()
 	steps, failed := s.steps, s.failed
@@ -75,5 +116,9 @@ func (s *Shutdown) Done(attrs ...any) {
 		s.log.Warn("stopped with errors during shutdown", append(fields, "failed_steps", failed)...)
 		return
 	}
+	if s.caused {
+		s.log.Warn("stopped after a failure", fields...)
+		return
+	}
 	s.log.Info("stopped cleanly", fields...)
 }

go/kit/logging/file.go

@@ -55,13 +55,18 @@ const (
 // lexically in chronological order, which is what makes the history readable.
 const rollStamp = "20060102T150405"
 
-func newRotator(o Options) (*rotator, error) {
+// newRotator opens the live file and prunes once. now is the clock seam; nil
+// means time.Now. It is a parameter rather than a field the caller sets after
+// the fact because the startup prune below runs during construction — a clock
+// installed on the returned value arrives too late to affect it, which is a
+// seam that silently does nothing.
+func newRotator(o Options, now func() time.Time) (*rotator, error) {
 	if dir := filepath.Dir(o.File); dir != "" && dir != "." {
 		if err := os.MkdirAll(dir, logDirMode); err != nil {
 			return nil, fmt.Errorf("log.file: %w", err)
 		}
 	}
-	r := &rotator{opts: o}
+	r := &rotator{opts: o, now: now}
 	if err := r.open(); err != nil {
 		return nil, err
 	}

go/kit/logging/logging.go

@@ -239,7 +239,7 @@ func New(o Options) (*Logger, error) {
 		out = console
 	}
 	if o.File != "" {
-		file, err := newRotator(o)
+		file, err := newRotator(o, nil)
 		if err != nil {
 			return nil, err
 		}

go/kit/logging/logging_test.go

@@ -216,12 +216,11 @@ func TestRollOnSize(t *testing.T) {
 func TestRollOnDayTurn(t *testing.T) {
 	dir := t.TempDir()
 	path := filepath.Join(dir, "svc.log")
-	r, err := newRotator(Options{File: path})
+	day := time.Date(2026, 8, 1, 23, 59, 0, 0, time.UTC)
+	r, err := newRotator(Options{File: path}, func() time.Time { return day })
 	if err != nil {
 		t.Fatal(err)
 	}
-	day := time.Date(2026, 8, 1, 23, 59, 0, 0, time.UTC)
-	r.now = func() time.Time { return day }
 	if _, err := r.Write([]byte("before midnight\n")); err != nil {
 		t.Fatal(err)
 	}
@@ -264,11 +263,19 @@ func TestRetainDaysDeletesOldRolls(t *testing.T) {
 		}
 	}
 
-	r, err := newRotator(Options{File: path, RetainDays: 14})
+	// The clock goes in at construction, not after: newRotator prunes once
+	// during startup, so a clock installed on the returned value would arrive
+	// after the deletion it is meant to control. Passing it here also means
+	// this test covers the startup prune — the one that catches up after a
+	// service was down longer than its retention window — rather than only the
+	// explicit call below.
+	r, err := newRotator(Options{File: path, RetainDays: 14}, func() time.Time { return now })
 	if err != nil {
 		t.Fatal(err)
 	}
-	r.now = func() time.Time { return now }
+	if _, err := os.Stat(old); err == nil {
+		t.Fatal("the startup prune kept a roll past the retention window")
+	}
 	r.prune()
 	if err := r.Close(); err != nil {
 		t.Fatal(err)
@@ -297,11 +304,10 @@ func TestMaxFilesCapsRolls(t *testing.T) {
 			t.Fatal(err)
 		}
 	}
-	r, err := newRotator(Options{File: path, MaxFiles: 2})
+	r, err := newRotator(Options{File: path, MaxFiles: 2}, func() time.Time { return now })
 	if err != nil {
 		t.Fatal(err)
 	}
-	r.now = func() time.Time { return now }
 	r.prune()
 
 	kept := r.rolls()