KamadoPool/api/internal/logmon/tailer.go

// 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 <float>" 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: <hexhash>"
	//   "Rejected client 42 dupe diff 1234.5/65536/1.234G: <hexhash>"
	//   "Rejected client 42 high diff 1234.5/65536/1.234G: <hexhash>"
	//   "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 <reason>" — 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 <id> 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 <id> invalid share <reason>"
	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
// <id> <keyword> 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
	}
}