// Package logmon tails the ckpool log file looking for notable events — // primarily block-solve lines, which are the most reliable signal we have // that a block was found, short of a ZMQ hashblock subscription. // // ckpool-solo logs a line like: // // Solved and confirmed block 840123 // // from stratifier.c via LOGWARNING when a submitted share passes network // difficulty and bitcoind confirms acceptance. We parse these lines, // emit BlockEvent values on Events, and let the aggregator enrich them // with hash/reward via bitcoind RPC. package logmon import ( "bufio" "context" "errors" "io" "log/slog" "os" "regexp" "strconv" "strings" "time" ) // BlockEvent is emitted when the tailer sees a "Solved and confirmed block" // line in the ckpool log. Hash and worker are populated later by the // aggregator once it cross-references bitcoind. ShareDiff is the // difficulty of the winning share, captured from the "Possible block // solve" line that precedes the confirmation line. type BlockEvent struct { Height int64 `json:"height"` SeenAt time.Time `json:"seen_at"` RawLine string `json:"raw_line"` ShareDiff float64 `json:"share_diff,omitempty"` } // AttemptEvent is emitted when ckpool logs a "Possible block solve" // or "Submitting possible block solve" line — i.e. ckpool decided a // share met network difficulty and is attempting to submit it to // bitcoind. This precedes the "Solved and confirmed" line that drives // BlockEvent. Counting attempts vs confirmations surfaces submission // failures (bitcoind rejected, RPC timeout, etc.) that would otherwise // be invisible. type AttemptEvent struct { SeenAt time.Time ShareDiff float64 RawLine string } // LatencyEvent is emitted when ckpool logs the "Block update latency" // line from our patch 0005 — the milliseconds between ZMQ trigger and // mining.notify broadcast completion. type LatencyEvent struct { SeenAt time.Time LatencyMs int64 } // ShareEvent is emitted for every individual share submission logged by // ckpool (both accepted and rejected). Used to build rejection-reason // breakdowns and accepted-share difficulty distributions. type ShareEvent struct { SeenAt time.Time Diff float64 // share difficulty (always set for accepted; 0 for rejected) Hash string // block header hash (hex, accepted shares only) Rejected bool Reason string // rejection reason (e.g. "Stale", "Duplicate"); empty for accepted } // Tailer follows a log file, surviving rotation/truncation, and emits // parsed events. Create with New, then Run in a goroutine. type Tailer struct { Path string Events chan BlockEvent Attempts chan AttemptEvent Latencies chan LatencyEvent Shares chan ShareEvent Log *slog.Logger PollWait time.Duration // how long to sleep between EOF polls // LoadCursor / SaveCursor, if both non-nil, persist the read // position across process restarts. LoadCursor returns (inode, // offset, true) when a saved cursor exists for this path; the // tailer will resume from offset only if the inode still matches. // SaveCursor is invoked on a throttled cadence as we read, so a // crash loses at most ~1s of unread bytes. LoadCursor func() (inode uint64, offset int64, ok bool) SaveCursor func(inode uint64, offset int64) // lastSolveDiff remembers the share diff from the most recent // "Possible block solve" line so handleLine can attach it to the // subsequent "Solved and confirmed block" event. Reset after use. lastSolveDiff float64 lastCursorSave time.Time } func New(path string, log *slog.Logger) *Tailer { return &Tailer{ Path: path, Events: make(chan BlockEvent, 16), Attempts: make(chan AttemptEvent, 16), Latencies: make(chan LatencyEvent, 16), Shares: make(chan ShareEvent, 64), Log: log, PollWait: 500 * time.Millisecond, } } var ( solvedRE = regexp.MustCompile(`Solved and confirmed block\s+(\d+)`) // Matches the three "Possible ... block solve ... diff " lines // ckpool emits from stratifier.c right before a block is submitted: // "Possible block solve diff N !" // "Possible stale share block solve diff N !" // "Submitting possible block solve share diff N !" // "Possible remote block solve diff N !" solveDiffRE = regexp.MustCompile(`(?:Possible|Submitting[^"]*possible).*block solve.*diff\s+([0-9eE.+-]+)`) // Matches the latency line from our patch 0005: // "Block update latency: 92ms (ZMQ trigger to mining.notify broadcast)" latencyRE = regexp.MustCompile(`Block update latency:\s+(\d+)ms`) // Share events from ckpool's stratifier.c (v1.0 / cfb0f83b): // "Accepted client 42 share diff 1234.5/65536/1.234G: " // "Rejected client 42 dupe diff 1234.5/65536/1.234G: " // "Rejected client 42 high diff 1234.5/65536/1.234G: " // "Rejected client 42 invalid share Stale" // The first number after "diff " is sdiff (share difficulty solved). acceptedShareRE = regexp.MustCompile(`Accepted client \S+ share diff ([0-9.]+)/[^:]+:\s*([0-9a-fA-F]+)`) // Rejected shares come in two forms: // 1. "dupe diff" / "high diff" — share was valid but duplicate or below target // 2. "invalid share " — share was structurally invalid (Stale, etc.) rejectedDiffRE = regexp.MustCompile(`Rejected client \S+ (\w+) diff [0-9.]+/`) rejectedInvalRE = regexp.MustCompile(`Rejected client \S+ invalid share (.+)`) ) // Run blocks until ctx is cancelled. It opens the file, seeks to either // the saved cursor (if LoadCursor returns one and the inode still // matches) or the end on first-ever run, and reads new lines as they // are appended. If the file is rotated (shrinks, or inode changes), it // re-opens. func (t *Tailer) Run(ctx context.Context) { defer close(t.Events) defer close(t.Attempts) defer close(t.Latencies) defer close(t.Shares) var ( f *os.File reader *bufio.Reader lastIno uint64 lastPos int64 // firstOpen distinguishes the very first Open of this tailer // (where we honor LoadCursor and replay the backlog) from // rotation re-opens (where we always start at 0). firstOpen = true ) open := func() error { if f != nil { _ = f.Close() } nf, err := os.Open(t.Path) if err != nil { return err } st, err := nf.Stat() if err != nil { _ = nf.Close() return err } ino := inodeOf(st) size := st.Size() // Decide where to start reading. var startAt int64 if firstOpen { if t.LoadCursor != nil { if savedIno, savedOff, ok := t.LoadCursor(); ok && savedIno == ino && savedOff <= size { startAt = savedOff if savedOff < size { t.Log.Info("logmon: resuming from saved cursor", "path", t.Path, "offset", savedOff, "size", size) } } else { // No cursor, or stale (file was rotated since we // last saw it, so we have no way to know what we // already read). Start at end to avoid replaying // the entire log. startAt = size } } else { startAt = size } firstOpen = false } else { // Rotation: read the whole replacement file from the start. startAt = 0 } if _, err := nf.Seek(startAt, io.SeekStart); err != nil { _ = nf.Close() return err } f = nf reader = bufio.NewReader(f) lastIno = ino lastPos = startAt return nil } saveCursor := func(force bool) { if t.SaveCursor == nil || f == nil { return } now := time.Now() if !force && now.Sub(t.lastCursorSave) < time.Second { return } t.SaveCursor(lastIno, lastPos) t.lastCursorSave = now } // Initial open; retry on failure until the file exists. for { if err := open(); err != nil { t.Log.Warn("logmon: waiting for log file", "path", t.Path, "err", err) if !sleep(ctx, 2*time.Second) { return } continue } break } defer func() { if f != nil { _ = f.Close() } }() for { if ctx.Err() != nil { saveCursor(true) return } line, err := reader.ReadString('\n') if len(line) > 0 { t.handleLine(line) lastPos, _ = f.Seek(0, io.SeekCurrent) } if err == nil { continue } if !errors.Is(err, io.EOF) { t.Log.Warn("logmon: read error, reopening", "err", err) saveCursor(true) if !sleep(ctx, t.PollWait) { return } _ = open() continue } // EOF: persist where we are (caught up to current end), then // check for rotation (inode changed) or truncation (size < pos). saveCursor(false) if st, statErr := os.Stat(t.Path); statErr == nil { if inodeOf(st) != lastIno || st.Size() < lastPos { t.Log.Info("logmon: log rotated, reopening", "path", t.Path) if err := open(); err != nil { t.Log.Warn("logmon: reopen failed", "err", err) } continue } } if !sleep(ctx, t.PollWait) { saveCursor(true) return } } } func (t *Tailer) handleLine(line string) { // Accepted share: extract share difficulty and block header hash. if m := acceptedShareRE.FindStringSubmatch(line); m != nil { if d, err := strconv.ParseFloat(m[1], 64); err == nil { select { case t.Shares <- ShareEvent{SeenAt: time.Now(), Diff: d, Hash: m[2]}: default: } } // Don't return — an accepted share may also be a block solve, // so let the solve-diff regex below get a chance to match too. } // Rejected share with diff info: "Rejected client dupe|high diff ..." if m := rejectedDiffRE.FindStringSubmatch(line); m != nil { reason := rejectKeyword(m[1]) select { case t.Shares <- ShareEvent{SeenAt: time.Now(), Rejected: true, Reason: reason}: default: } return } // Rejected share without diff: "Rejected client invalid share " if m := rejectedInvalRE.FindStringSubmatch(line); m != nil { reason := strings.TrimSpace(m[1]) select { case t.Shares <- ShareEvent{SeenAt: time.Now(), Rejected: true, Reason: reason}: default: } return } if m := latencyRE.FindStringSubmatch(line); m != nil { if ms, err := strconv.ParseInt(m[1], 10, 64); err == nil { select { case t.Latencies <- LatencyEvent{SeenAt: time.Now(), LatencyMs: ms}: default: } } return } if m := solveDiffRE.FindStringSubmatch(line); m != nil { var d float64 if v, err := strconv.ParseFloat(m[1], 64); err == nil { d = v t.lastSolveDiff = v } select { case t.Attempts <- AttemptEvent{SeenAt: time.Now(), ShareDiff: d, RawLine: line}: default: // Best-effort metric — dropping is fine. } return } m := solvedRE.FindStringSubmatch(line) if m == nil { return } height, err := strconv.ParseInt(m[1], 10, 64) if err != nil { return } ev := BlockEvent{ Height: height, SeenAt: time.Now(), RawLine: line, ShareDiff: t.lastSolveDiff, } t.lastSolveDiff = 0 select { case t.Events <- ev: t.Log.Info("logmon: block solved", "height", height, "share_diff", ev.ShareDiff) default: t.Log.Warn("logmon: events channel full, dropping", "height", height) } } // rejectKeyword maps the short keyword ckpool uses in "Rejected client // diff ..." log lines to a human-readable reason. func rejectKeyword(kw string) string { switch strings.ToLower(kw) { case "dupe": return "Duplicate" case "high": return "Above target" default: return kw } } // FindBestShareHash scans the log file for the accepted share with the // highest difficulty and returns its diff and block header hash. Used as // a one-time backfill when bestDiff is persisted but the hash is not // (pre-upgrade shares). Returns (0, "") if no accepted shares are found. func FindBestShareHash(path string) (float64, string) { f, err := os.Open(path) if err != nil { return 0, "" } defer f.Close() var bestDiff float64 var bestHash string scanner := bufio.NewScanner(f) scanner.Buffer(make([]byte, 0, 64*1024), 256*1024) for scanner.Scan() { line := scanner.Text() if !strings.Contains(line, "Accepted client") { continue } m := acceptedShareRE.FindStringSubmatch(line) if m == nil { continue } d, err := strconv.ParseFloat(m[1], 64) if err != nil { continue } if d >= bestDiff { bestDiff = d bestHash = m[2] } } return bestDiff, bestHash } // sleep returns false if ctx was cancelled during the wait. func sleep(ctx context.Context, d time.Duration) bool { select { case <-ctx.Done(): return false case <-time.After(d): return true } }