admin
7d64038f02
gates / gates (push) Successful in 6m45s
Hub: the R-120 golden guard judges only a CHANGED golden selection; offsite_snapshots_vanished / _unexplained (operator-only, hub-origin) on the 07:10 listing; internal/accesslog writes path-only lines to /data/access-log, 90 days. Installer: --rotate-recovery-only runs step 4b alone (rides the next installer tag). 03: the orphan check runs after a failed backup (agent 6545ccc). 02: the allow-list is empty, appdata_folders (controller v0.329.0). All red-proofed.
397 lines
11 KiB
Go
397 lines
11 KiB
Go
// Package accesslog is the hub's OWN access log (R-1140, operator decision A 2026-10-17 22:26: „a separate log for the
|
||
// hub only"; `05` §16.4). One line per request the hub serves, in a file per UTC day on the hub's own volume
|
||
// (`<data_dir>/access-log/access-YYYY-MM-DD.log`), kept 90 days and then deleted.
|
||
//
|
||
// WHY: R-954 asked „did anyone use the old hub key before 2026-10-12?" and could not be answered — the ingress
|
||
// controller's container log covers about half a day (k3s rotates it at 10 MiB × 5), and the hub logged no requests.
|
||
//
|
||
// WHAT A LINE HOLDS — and what it never holds. Example:
|
||
//
|
||
// 2026-10-17T20:35:16Z POST /api/v1/report 200 12ms remote=10.42.0.31 xff=192.168.0.149 cred=bearer auth=customer
|
||
//
|
||
// The PATH only: the query string is dropped entirely (it can carry a token), and a path segment that is a capability
|
||
// (`/bind/<token>`) or any segment of 32+ characters is written as `[redacted]` (TestAccessLog_NeverWritesASecret).
|
||
// remote is the socket peer (behind ingress-nginx: the ingress pod); xff is the X-Forwarded-For header as the hub
|
||
// received it, each hop kept only if it parses as an IP address (anything else is written as `?`). Neither is trusted
|
||
// for anything; both are recorded so the reader can judge. cred is the KIND of credential presented (bearer, token,
|
||
// basic, session-cookie, passphrase), read from header names and prefixes — never a value. auth is the identity the
|
||
// hub's own auth helpers ESTABLISHED (customer, host, global, session, basic, token), set through Mark; `-` when none
|
||
// did (a public route, a refusal, or a handler's own check).
|
||
//
|
||
// A LOGGING FAILURE NEVER FAILS OR DELAYS A REQUEST. The middleware hands the line to a buffered channel without
|
||
// blocking; a single writer goroutine does every file operation. A full buffer drops the line and counts it; an
|
||
// unwritable directory is reported (rate-limited) and the request is served as before.
|
||
//
|
||
// kube-probe's own /healthz requests (no X-Forwarded-For, User-Agent kube-probe/…) are not logged: 11,520 lines a day
|
||
// that say nothing, and they would be 85 % of the file. A /healthz that came through the ingress is logged.
|
||
package accesslog
|
||
|
||
import (
|
||
"context"
|
||
"fmt"
|
||
"net"
|
||
"net/http"
|
||
"os"
|
||
"path/filepath"
|
||
"regexp"
|
||
"sort"
|
||
"strings"
|
||
"sync"
|
||
"time"
|
||
)
|
||
|
||
// DefaultKeep is how long a day's file is kept (operator decision A on R-1140: 90 days).
|
||
const DefaultKeep = 90 * 24 * time.Hour
|
||
|
||
const bufferLines = 2048
|
||
|
||
var fileRe = regexp.MustCompile(`^access-(\d{4}-\d{2}-\d{2})\.log$`)
|
||
|
||
// Log is the hub's access log. Zero values are not usable; build it with New.
|
||
type Log struct {
|
||
dir string
|
||
keep time.Duration
|
||
now func() time.Time
|
||
logf func(format string, a ...any)
|
||
|
||
ch chan string
|
||
done chan struct{}
|
||
|
||
// writer-goroutine state (touched only by run)
|
||
f *os.File
|
||
day string
|
||
lastPrune string
|
||
lastErrAt time.Time
|
||
|
||
mu sync.Mutex
|
||
dropped int64
|
||
closed bool
|
||
}
|
||
|
||
// Options configure New. Now and Logf are seams for tests; nil → time.Now / discard. Logf receives the access log's
|
||
// own operational lines (a rate-limited write failure, a prune) — never a request line.
|
||
type Options struct {
|
||
Dir string
|
||
Keep time.Duration
|
||
Now func() time.Time
|
||
Logf func(format string, a ...any)
|
||
}
|
||
|
||
// New starts the writer and prunes once. The directory is created on first write, never at construction, so a
|
||
// missing volume costs a logged error and nothing else.
|
||
func New(o Options) *Log {
|
||
l := &Log{dir: o.Dir, keep: o.Keep, now: o.Now, logf: o.Logf,
|
||
ch: make(chan string, bufferLines), done: make(chan struct{})}
|
||
if l.keep <= 0 {
|
||
l.keep = DefaultKeep
|
||
}
|
||
if l.now == nil {
|
||
l.now = time.Now
|
||
}
|
||
if l.logf == nil {
|
||
l.logf = func(string, ...any) {}
|
||
}
|
||
go l.run()
|
||
return l
|
||
}
|
||
|
||
// Close drains the buffer, closes the file and stops the writer. Safe to call twice.
|
||
func (l *Log) Close() {
|
||
l.mu.Lock()
|
||
if l.closed {
|
||
l.mu.Unlock()
|
||
return
|
||
}
|
||
l.closed = true
|
||
close(l.ch)
|
||
l.mu.Unlock()
|
||
<-l.done
|
||
}
|
||
|
||
// Dropped is how many lines a full buffer (or a closed log) refused.
|
||
func (l *Log) Dropped() int64 {
|
||
l.mu.Lock()
|
||
defer l.mu.Unlock()
|
||
return l.dropped
|
||
}
|
||
|
||
func (l *Log) enqueue(line string) {
|
||
l.mu.Lock()
|
||
defer l.mu.Unlock()
|
||
if l.closed {
|
||
l.dropped++
|
||
return
|
||
}
|
||
select {
|
||
case l.ch <- line:
|
||
default:
|
||
l.dropped++
|
||
}
|
||
}
|
||
|
||
func (l *Log) run() {
|
||
defer close(l.done)
|
||
l.prune()
|
||
for line := range l.ch {
|
||
l.write(line)
|
||
}
|
||
if l.f != nil {
|
||
_ = l.f.Close()
|
||
}
|
||
}
|
||
|
||
func (l *Log) fail(what string, err error) {
|
||
// One report a minute at most: a full or missing volume must not flood the hub's own log.
|
||
if now := l.now(); now.Sub(l.lastErrAt) >= time.Minute {
|
||
l.lastErrAt = now
|
||
l.logf("[WARN] access log: %s: %v (the request was served; this line is lost)", what, err)
|
||
}
|
||
}
|
||
|
||
func (l *Log) write(line string) {
|
||
day := l.now().UTC().Format("2006-01-02")
|
||
if l.f == nil || day != l.day {
|
||
if l.f != nil {
|
||
_ = l.f.Close()
|
||
l.f = nil
|
||
}
|
||
if err := os.MkdirAll(l.dir, 0o700); err != nil {
|
||
l.fail("create "+l.dir, err)
|
||
return
|
||
}
|
||
f, err := os.OpenFile(filepath.Join(l.dir, "access-"+day+".log"), os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o600)
|
||
if err != nil {
|
||
l.fail("open the day's file", err)
|
||
return
|
||
}
|
||
l.f, l.day = f, day
|
||
if day != l.lastPrune {
|
||
l.prune()
|
||
}
|
||
}
|
||
if _, err := l.f.WriteString(line); err != nil {
|
||
l.fail("write", err)
|
||
}
|
||
}
|
||
|
||
// prune deletes day files older than keep. Only names of the exact form access-YYYY-MM-DD.log are ever removed.
|
||
func (l *Log) prune() {
|
||
now := l.now().UTC()
|
||
l.lastPrune = now.Format("2006-01-02")
|
||
cutoff := now.Add(-l.keep).Format("2006-01-02")
|
||
ents, err := os.ReadDir(l.dir)
|
||
if err != nil {
|
||
if !os.IsNotExist(err) {
|
||
l.fail("read "+l.dir, err)
|
||
}
|
||
return
|
||
}
|
||
var removed []string
|
||
for _, e := range ents {
|
||
m := fileRe.FindStringSubmatch(e.Name())
|
||
if m == nil || e.IsDir() {
|
||
continue
|
||
}
|
||
if _, perr := time.Parse("2006-01-02", m[1]); perr != nil {
|
||
continue
|
||
}
|
||
if m[1] < cutoff {
|
||
if err := os.Remove(filepath.Join(l.dir, e.Name())); err != nil {
|
||
l.fail("remove "+e.Name(), err)
|
||
continue
|
||
}
|
||
removed = append(removed, e.Name())
|
||
}
|
||
}
|
||
if len(removed) > 0 {
|
||
sort.Strings(removed)
|
||
l.logf("[INFO] access log: removed %d day file(s) older than %d days: %s", len(removed), int(l.keep.Hours()/24), strings.Join(removed, ", "))
|
||
}
|
||
}
|
||
|
||
// ── identity marks ──────────────────────────────────────────────────────────────────────────────────
|
||
|
||
type ctxKey struct{}
|
||
|
||
type entry struct {
|
||
mu sync.Mutex
|
||
auth string
|
||
}
|
||
|
||
// Mark records the identity kind an auth helper established for this request ("customer", "host", "global",
|
||
// "session", "basic", "token"). A KIND only — never a name, a key or a token. No-op outside the middleware.
|
||
func Mark(ctx context.Context, kind string) {
|
||
if e, ok := ctx.Value(ctxKey{}).(*entry); ok {
|
||
e.mu.Lock()
|
||
e.auth = kind
|
||
e.mu.Unlock()
|
||
}
|
||
}
|
||
|
||
// ── the middleware ──────────────────────────────────────────────────────────────────────────────────
|
||
|
||
type recorder struct {
|
||
http.ResponseWriter
|
||
status int
|
||
}
|
||
|
||
func (r *recorder) WriteHeader(code int) {
|
||
if r.status == 0 {
|
||
r.status = code
|
||
}
|
||
r.ResponseWriter.WriteHeader(code)
|
||
}
|
||
|
||
func (r *recorder) Write(b []byte) (int, error) {
|
||
if r.status == 0 {
|
||
r.status = http.StatusOK
|
||
}
|
||
return r.ResponseWriter.Write(b)
|
||
}
|
||
|
||
// Flush and Unwrap keep http.ResponseController (the /api/v1/wait long-poll's Flush and SetWriteDeadline) working.
|
||
func (r *recorder) Flush() {
|
||
if f, ok := r.ResponseWriter.(http.Flusher); ok {
|
||
f.Flush()
|
||
}
|
||
}
|
||
|
||
func (r *recorder) Unwrap() http.ResponseWriter { return r.ResponseWriter }
|
||
|
||
// Middleware logs every request next serves. nil l → next unchanged.
|
||
func (l *Log) Middleware(next http.Handler) http.Handler {
|
||
if l == nil {
|
||
return next
|
||
}
|
||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||
if r.URL.Path == "/healthz" && r.Header.Get("X-Forwarded-For") == "" && strings.HasPrefix(r.UserAgent(), "kube-probe/") {
|
||
next.ServeHTTP(w, r)
|
||
return
|
||
}
|
||
start := l.now()
|
||
e := &entry{}
|
||
rec := &recorder{ResponseWriter: w}
|
||
finished := false
|
||
defer func() {
|
||
status := fmt.Sprint(rec.status)
|
||
if !finished {
|
||
status = "panic"
|
||
} else if rec.status == 0 {
|
||
status = "200"
|
||
}
|
||
e.mu.Lock()
|
||
auth := e.auth
|
||
e.mu.Unlock()
|
||
l.enqueue(FormatLine(start, r, status, l.now().Sub(start), auth))
|
||
}()
|
||
next.ServeHTTP(rec, r.WithContext(context.WithValue(r.Context(), ctxKey{}, e)))
|
||
finished = true
|
||
})
|
||
}
|
||
|
||
// FormatLine renders one line. Exported for the size measurement and the tests; it reads only the method, the PATH,
|
||
// the socket peer, X-Forwarded-For (IPs only) and the NAMES/prefixes of the credential headers.
|
||
func FormatLine(start time.Time, r *http.Request, status string, dur time.Duration, auth string) string {
|
||
if auth == "" {
|
||
auth = "-"
|
||
}
|
||
remote := r.RemoteAddr
|
||
if h, _, err := net.SplitHostPort(remote); err == nil {
|
||
remote = h
|
||
}
|
||
return fmt.Sprintf("%s %s %s %s %dms remote=%s xff=%s cred=%s auth=%s\n",
|
||
start.UTC().Format("2006-01-02T15:04:05Z"), safeToken(r.Method, 10), SafePath(r), status,
|
||
dur.Milliseconds(), safeIP(remote), safeXFF(r.Header.Get("X-Forwarded-For")), credKind(r), auth)
|
||
}
|
||
|
||
// SafePath is the request path with no query string, escaped (no space or newline can reach the file), with capability
|
||
// segments redacted, at most 256 bytes.
|
||
func SafePath(r *http.Request) string {
|
||
p := r.URL.EscapedPath()
|
||
if p == "" {
|
||
p = "/"
|
||
}
|
||
segs := strings.Split(p, "/")
|
||
for i, s := range segs {
|
||
switch {
|
||
case i > 0 && segs[i-1] == "bind" && i == 2: // /bind/<token>[/resend] — the self-bind capability
|
||
segs[i] = "[redacted]"
|
||
case len(s) >= 32:
|
||
segs[i] = "[redacted]"
|
||
}
|
||
}
|
||
p = strings.Join(segs, "/")
|
||
if len(p) > 256 {
|
||
p = p[:256] + "…"
|
||
}
|
||
return p
|
||
}
|
||
|
||
func safeToken(s string, max int) string {
|
||
var b strings.Builder
|
||
for _, c := range s {
|
||
if c >= 'A' && c <= 'Z' || c >= 'a' && c <= 'z' {
|
||
b.WriteRune(c)
|
||
}
|
||
}
|
||
if b.Len() == 0 || b.Len() > max {
|
||
return "?"
|
||
}
|
||
return b.String()
|
||
}
|
||
|
||
func safeIP(s string) string {
|
||
if ip := net.ParseIP(strings.TrimSpace(s)); ip != nil {
|
||
return ip.String()
|
||
}
|
||
if s == "" {
|
||
return "-"
|
||
}
|
||
return "?"
|
||
}
|
||
|
||
func safeXFF(h string) string {
|
||
if strings.TrimSpace(h) == "" {
|
||
return "-"
|
||
}
|
||
var hops []string
|
||
for i, part := range strings.Split(h, ",") {
|
||
if i == 8 {
|
||
hops = append(hops, "…")
|
||
break
|
||
}
|
||
hops = append(hops, safeIP(part))
|
||
}
|
||
return strings.Join(hops, ",")
|
||
}
|
||
|
||
// credKind names the credential presented — never its value.
|
||
func credKind(r *http.Request) string {
|
||
var kinds []string
|
||
if a := r.Header.Get("Authorization"); a != "" {
|
||
switch {
|
||
case strings.HasPrefix(a, "Bearer fhp_"):
|
||
kinds = append(kinds, "token")
|
||
case strings.HasPrefix(a, "Bearer "):
|
||
kinds = append(kinds, "bearer")
|
||
case strings.HasPrefix(a, "Basic "):
|
||
kinds = append(kinds, "basic")
|
||
default:
|
||
kinds = append(kinds, "other")
|
||
}
|
||
}
|
||
for _, c := range r.Cookies() {
|
||
if strings.HasSuffix(c.Name, "hub_session") {
|
||
kinds = append(kinds, "session-cookie")
|
||
break
|
||
}
|
||
}
|
||
if r.Header.Get("X-Retrieval-Password") != "" {
|
||
kinds = append(kinds, "passphrase")
|
||
}
|
||
if len(kinds) == 0 {
|
||
return "-"
|
||
}
|
||
return strings.Join(kinds, "+")
|
||
}
|