From 9a3044a564f757d7f398bd4a6a457ef64e8da655 Mon Sep 17 00:00:00 2001 From: Hoshi <132435834+hoshimoe@users.noreply.github.com> Date: Sat, 15 Aug 2026 11:27:48 +0000 Subject: [PATCH 1/2] =?UTF-8?q?logging=EF=BC=9A=E6=99=82=E9=90=98=20seam?= =?UTF-8?q?=20=E7=A7=BB=E5=88=B0=20newRotator=20=E7=9A=84=E5=8F=83?= =?UTF-8?q?=E6=95=B8=EF=BC=8C=E4=BF=AE=E5=A5=BD=E6=9C=83=E9=81=8E=E6=9C=9F?= =?UTF-8?q?=E7=9A=84=E4=BF=9D=E7=95=99=E6=9C=9F=E6=B8=AC=E8=A9=A6?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit newRotator 在建構時就 prune 一次（服務停機久於保留窗時要補刪），而測試是在 它回傳之後才裝上 r.now——那個時鐘來得太晚，那次 prune 用的是真實時鐘。 測試把「保留窗內」那個檔固定寫在 2026-07-31，於是真實時間越過 cutoff（now-14d）的那一天起，建構時的 prune 就把它刪掉了，測試從此 單向轉紅。臨界點是 2026-08-14。 時鐘改成 newRotator 的參數（nil ＝ time.Now），在 prune 之前就位。 順帶讓這支測試真的涵蓋到啟動時那次 prune——它先前完全沒有被測到， 因為斷言前又呼叫了一次 prune，看起來像是那一次的功勞。 反向對照：拿掉保留期的刪除，測試在新的斷言上轉紅。 --- go/kit/logging/file.go | 9 +++++++-- go/kit/logging/logging.go | 2 +- go/kit/logging/logging_test.go | 20 +++++++++++++------- 3 files changed, 21 insertions(+), 10 deletions(-) diff --git a/go/kit/logging/file.go b/go/kit/logging/file.go index a2ac4da..2bdeeff 100644 --- a/go/kit/logging/file.go +++ b/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 } diff --git a/go/kit/logging/logging.go b/go/kit/logging/logging.go index 920d5bb..a4dedef 100644 --- a/go/kit/logging/logging.go +++ b/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 } diff --git a/go/kit/logging/logging_test.go b/go/kit/logging/logging_test.go index ea590a8..a65a629 100644 --- a/go/kit/logging/logging_test.go +++ b/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() From 0f088f7f63d8aeff032e972e78d829d30478a877 Mon Sep 17 00:00:00 2001 From: Hoshi <132435834+hoshimoe@users.noreply.github.com> Date: Sat, 15 Aug 2026 14:17:10 +0000 Subject: [PATCH 2/2] =?UTF-8?q?lifecycle=EF=BC=9A=E8=A2=AB=E9=80=BC?= =?UTF-8?q?=E5=81=9C=E7=9A=84=E9=97=9C=E6=A9=9F=E8=B5=B0=20BeginFailure?= =?UTF-8?q?=EF=BC=8C=E5=8E=9F=E5=A7=8B=20error=20=E6=98=AF=E4=B8=80?= =?UTF-8?q?=E7=AD=86=20error=20=E7=B4=80=E9=8C=84?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit BeginShutdown 的 announce 一律 info，而採用它的服務都把「是什麼逼停了我」 當成那一行的欄位傳進去。結果是：跑在 log.level: warn 的部署——也就是最需要 這筆紀錄的那些——listener 起不來時，那個 error 不存在於任何一筆 error 紀錄裡， 行程就這麼消失，什麼都沒留下。 新增 BeginFailure(log, reason, err, attrs...)： - 觸發的 error 走 **Error**，帶著是什麼掛了； - Done() 之後**不會**說 "stopped cleanly" 而是 "stopped after a failure"， 即使每個拆解步驟都成功——收拾得乾淨不等於停得乾淨，而在 warn 底下那行 總結本來會是唯一活下來的一行； - err 傳 nil 代表沒有東西逼停它，等同 BeginShutdown（單一程式路徑的呼叫端 不會意外變吵）。 BeginShutdown 一個位元組都沒動：有秩序的停止維持 info，跑在 warn 的部署 看不到它是刻意的，例行重啟不該每次都喊。成功的步驟也維持 debug。 測試改成斷言**某個層級的部署實際看得到什麼**，而不是斷言呼叫了什麼——這個 差別只在 info 以上才存在，在 debug 底下驗不出來。四支：warn 底下失敗關機 聽得到（且成功步驟不會漏出來）、warn 底下正常關機完全靜默、失敗的 step 即使在正常關機裡也是 error、nil cause 等同 BeginShutdown。把原因行退回 info 可讓第一支轉紅，已實測。 --- go/README.md | 15 ++++ go/kit/lifecycle/lifecycle_test.go | 124 +++++++++++++++++++++++++++++ go/kit/lifecycle/shutdown.go | 51 +++++++++++- 3 files changed, 187 insertions(+), 3 deletions(-) diff --git a/go/README.md b/go/README.md index 78ae312..1b8e642 100644 --- a/go/README.md +++ b/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 diff --git a/go/kit/lifecycle/lifecycle_test.go b/go/kit/lifecycle/lifecycle_test.go index a4d3f58..2267e5b 100644 --- a/go/kit/lifecycle/lifecycle_test.go +++ b/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) + } +} diff --git a/go/kit/lifecycle/shutdown.go b/go/kit/lifecycle/shutdown.go index fb3213a..b3258e3 100644 --- a/go/kit/lifecycle/shutdown.go +++ b/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...) }