diff --git a/.dockerignore b/.dockerignore index a333f73..dea0dec 100644 --- a/.dockerignore +++ b/.dockerignore @@ -11,6 +11,7 @@ !destination/ !discovery/ !eth/ +!internal/ !nodeconfig/ !orchestrator/ !pm/ diff --git a/destination/policy.go b/destination/policy.go index 65ae890..bf15eeb 100644 --- a/destination/policy.go +++ b/destination/policy.go @@ -14,6 +14,9 @@ import ( "time" ) +// ErrDeniedAddress identifies a destination blocked by the grants policy. +var ErrDeniedAddress = errors.New("destination contains a denied address; configure grants for this purpose") + var deniedV4 = mustPrefixes( "0.0.0.0/8", "10.0.0.0/8", "100.64.0.0/10", "127.0.0.0/8", "169.254.0.0/16", "172.16.0.0/12", "192.0.0.0/24", "192.0.2.0/24", @@ -149,7 +152,7 @@ func (p Policy) DialContext(ctx context.Context, network, address string) (net.C } for _, ip := range ips { if !Public(ip) && !p.granted(net.JoinHostPort(ip.String(), port)) { - return nil, fmt.Errorf("%s destination contains a denied address; configure grants for this purpose", p.Purpose) + return nil, fmt.Errorf("%s %w", p.Purpose, ErrDeniedAddress) } } dialer := net.Dialer{Timeout: 10 * time.Second, KeepAlive: 30 * time.Second} diff --git a/discovery/app.go b/discovery/app.go index 3424828..d5d7ecc 100644 --- a/discovery/app.go +++ b/discovery/app.go @@ -86,11 +86,9 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { } defer metricsListener.Close() metrics := http.NewServeMux() - for path, body := range map[string]string{"/healthz": "ok\n", "/readyz": "ready\n", "/metrics": "livepeer_discovery_up 1\n"} { + metrics.Handle("GET /metrics", app.metrics.Handler()) + for path, body := range map[string]string{"/healthz": "ok\n", "/readyz": "ready\n"} { metrics.HandleFunc("GET "+path, func(w http.ResponseWriter, _ *http.Request) { - if path == "/metrics" { - w.Header().Set("Content-Type", "text/plain; version=0.0.4") - } _, _ = io.WriteString(w, body) }) } diff --git a/discovery/app_test.go b/discovery/app_test.go index 396c4d5..b982301 100644 --- a/discovery/app_test.go +++ b/discovery/app_test.go @@ -10,6 +10,7 @@ import ( "net/url" "os" "path/filepath" + "strings" "testing" "time" @@ -70,7 +71,11 @@ func TestServeWithoutRunnerOrPaymentDependencies(t *testing.T) { require.NoError(t, err) require.NoError(t, response.Body.Close()) require.Equal(t, 200, response.StatusCode) - require.Equal(t, want, string(body)) + if strings.HasSuffix(path, "/metrics") { + require.Contains(t, string(body), want) + } else { + require.Equal(t, want, string(body)) + } } }) } diff --git a/discovery/server.go b/discovery/server.go index 987de4c..69bea9c 100644 --- a/discovery/server.go +++ b/discovery/server.go @@ -13,6 +13,7 @@ import ( "github.com/livepeer/node/destination" discovery "github.com/livepeer/node/discovery/shared" + "github.com/livepeer/node/internal/observability" ) type discoveryNode struct { @@ -20,6 +21,7 @@ type discoveryNode struct { QueriedAt time.Time `json:"queried_at"` } type Server struct { + metrics *observability.Metrics logger *slog.Logger mux *http.ServeMux urls []*url.URL @@ -71,10 +73,11 @@ func NewServer(p Params, logger *slog.Logger) (*Server, error) { client := policy.Client() client.Timeout = 3 * time.Second client.CheckRedirect = func(*http.Request, []*http.Request) error { return http.ErrUseLastResponse } - s := &Server{logger: logger, mux: http.NewServeMux(), + metrics := observability.New("discovery") + s := &Server{metrics: metrics, logger: logger.With("component", "discovery"), mux: http.NewServeMux(), urls: urls, interval: p.RefreshInterval, advertiseNodes: p.AdvertiseNodes, advertiseRunners: p.AdvertiseRunners, - collector: &discovery.Collector[discoveryRunner]{Client: client, MaxFailures: max(1, p.MaxFailedRefreshes), Logger: logger}} + collector: &discovery.Collector[discoveryRunner]{Client: client, MaxFailures: max(1, p.MaxFailedRefreshes), Logger: logger.With("component", "discovery"), Observe: metrics.Discovery}} endpoints := make([]*url.URL, 0, len(urls)) for _, base := range urls { endpoint := base.Clone() @@ -86,10 +89,18 @@ func NewServer(p Params, logger *slog.Logger) (*Server, error) { } s.collector.SetSources(endpoints) s.mux.HandleFunc("GET /discovery", s.discovery) + metrics.Snapshot(s.collector.CollectMetrics) + metrics.Legacy(func(emit observability.Emit) { emit("discovery_up", 1, nil) }) return s, nil } -func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { s.mux.ServeHTTP(w, r) } +func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { + s.metrics.HTTP(w, r, func(w http.ResponseWriter, r *http.Request) { + _, pattern := s.mux.Handler(r) + observability.Operation(r, pattern) + s.mux.ServeHTTP(w, r) + }) +} func (s *Server) Close() { s.collector.Close() } diff --git a/discovery/shared/collector.go b/discovery/shared/collector.go index d22016c..951ee75 100644 --- a/discovery/shared/collector.go +++ b/discovery/shared/collector.go @@ -5,20 +5,25 @@ import ( "errors" "fmt" "log/slog" + "net" "net/http" "net/url" "slices" "strings" "sync" "time" + + "github.com/livepeer/node/destination" + "github.com/livepeer/node/internal/observability" ) // Snapshot is an immutable successful inventory observation. type Snapshot[R Runner] struct { - URL string - QueriedAt time.Time - Entries []Entry[R] - Failures int + URL string + QueriedAt time.Time + Entries []Entry[R] + Failures int + LastSuccess time.Time } // Collector polls complete discovery endpoints and retains per-source inventories. @@ -27,6 +32,7 @@ type Collector[R Runner] struct { Client *http.Client Logger *slog.Logger MaxFailures int + Observe func(int, time.Duration, error) mu sync.Mutex sources []*Snapshot[R] pending chan struct{} @@ -141,7 +147,11 @@ feedLoop: } workers.Go(func() { defer func() { <-slots }() + started := time.Now() entries, err := c.fetch(ctx, source.URL) + if c.Observe != nil { + c.Observe(index, time.Since(started), err) + } if ctx.Err() != nil { return } @@ -150,6 +160,7 @@ feedLoop: if err == nil { source.Entries = entries source.QueriedAt = time.Now().UTC() + source.LastSuccess = source.QueriedAt source.Failures = 0 c.initialized = true } else { @@ -166,13 +177,24 @@ feedLoop: if logger == nil { logger = slog.Default() } - logger.WarnContext(ctx, "discovery refresh failed", "source_index", index, "error", err) + kind := observability.ErrorKind(err) + var dns *net.DNSError + if errors.Is(err, destination.ErrDeniedAddress) { + kind = "denied_destination" + } else if errors.As(err, &dns) { + kind = "dns" + } else if errors.Is(err, errInvalidRedirect) { + kind = "invalid_redirect" + } + logger.WarnContext(ctx, "discovery refresh failed", "event", "discovery_refresh", "operation", "refresh", "outcome", "error", "source_index", index, "error_kind", kind) } }) } workers.Wait() } +var errInvalidRedirect = errors.New("invalid discovery redirect URL") + func (c *Collector[R]) fetch(ctx context.Context, endpoint string) ([]Entry[R], error) { req, err := http.NewRequestWithContext(ctx, http.MethodGet, endpoint, nil) if err != nil { @@ -186,7 +208,7 @@ func (c *Collector[R]) fetch(ctx context.Context, endpoint string) ([]Entry[R], } // Go includes the raw Location URL in this error, even after unwrapping. if strings.HasPrefix(err.Error(), "failed to parse Location header ") { - err = errors.New("invalid discovery redirect URL") + err = errInvalidRedirect } return nil, err } diff --git a/discovery/shared/collector_test.go b/discovery/shared/collector_test.go index dc038f2..9051ce7 100644 --- a/discovery/shared/collector_test.go +++ b/discovery/shared/collector_test.go @@ -14,6 +14,8 @@ import ( "time" "github.com/livepeer/node/destination" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" "github.com/stretchr/testify/require" ) @@ -28,8 +30,30 @@ func TestCollectorCacheLifecycle(t *testing.T) { status, body := 200, envelope(candidate("1999-01-01T00:00:00Z")) c := &Collector[record]{MaxFailures: 6, Client: &http.Client{Transport: collectorTransport(func(*http.Request) (*http.Response, error) { return collectorResponse(status, body), nil })}} c.SetSources([]*url.URL{{Scheme: "https", Host: "source.example"}}) + m := observability.New("discovery") + m.Snapshot(c.CollectMetrics) + assertMetrics := func(state string, count, failures int, last time.Time) { + t.Helper() + require.Len(t, test.MetricSamples(t, m.Registry, "discovery_source_state", nil), 4) + for _, candidate := range []string{"uninitialized", "healthy", "retained", "evicted"} { + require.Equal(t, observability.Bool(candidate == state), test.MetricSum(t, m.Registry, "discovery_source_state", map[string]string{"state": candidate})) + } + wantLast := 0.0 + if !last.IsZero() { + wantLast = float64(last.Unix()) + } + require.Equal(t, wantLast, test.MetricSum(t, m.Registry, "discovery_last_success_timestamp_seconds", nil)) + require.EqualValues(t, count, test.MetricSum(t, m.Registry, "discovery_cached_runners", nil)) + require.EqualValues(t, failures, test.MetricSum(t, m.Registry, "discovery_source_failures", nil)) + } + assertMetrics("uninitialized", 0, 0, time.Time{}) + status = 500 + c.Refresh(t.Context(), false) + assertMetrics("uninitialized", 0, 1, time.Time{}) + status = 200 c.Refresh(t.Context(), false) original := c.Snapshots()[0] + assertMetrics("healthy", 1, 0, original.LastSuccess) for i, failure := range []struct { status int body string @@ -40,22 +64,27 @@ func TestCollectorCacheLifecycle(t *testing.T) { c.Refresh(t.Context(), false) got := c.Snapshots()[0] require.Equal(t, original.Entries, got.Entries) + require.Equal(t, original.LastSuccess, got.LastSuccess) + assertMetrics("retained", 1, i+1, original.LastSuccess) require.Equal(t, original.QueriedAt, got.QueriedAt) require.Equal(t, i+1, got.Failures) } c.Refresh(t.Context(), false) require.Empty(t, c.Snapshots()) + assertMetrics("evicted", 0, 6, original.LastSuccess) require.True(t, c.Initialized(), "eviction does not reset startup") status, body = 200, envelope(candidate("1999-02-01T00:00:00Z")) c.Refresh(t.Context(), false) require.Equal(t, "1999-02-01T00:00:00Z", c.Snapshots()[0].Entries[0].Runners[0].Observed) require.Zero(t, c.Snapshots()[0].Failures) + assertMetrics("healthy", 1, 0, c.Snapshots()[0].LastSuccess) status = 500 c.Refresh(t.Context(), false) status, body = 200, "[]" c.Refresh(t.Context(), false) require.Len(t, c.Snapshots(), 1, "empty success is still a usable source") require.Empty(t, c.Snapshots()[0].Entries) + assertMetrics("healthy", 0, 0, c.Snapshots()[0].LastSuccess) require.Zero(t, c.Snapshots()[0].Failures) } @@ -136,10 +165,10 @@ func TestCollectorFailureDiagnostics(t *testing.T) { name, endpoint, want string transport http.RoundTripper }{ - {"grant", "http://127.0.0.1/private-token", "denied address", policy.Client().Transport}, - {"DNS", "https://missing.example/private-token", "no such host", policy.Client().Transport}, - {"timeout", "https://source.example/private-token", "context deadline exceeded", collectorTransport(func(*http.Request) (*http.Response, error) { return nil, context.DeadlineExceeded })}, - {"redirect", "https://source.example/private-token", "invalid discovery redirect URL", collectorTransport(func(*http.Request) (*http.Response, error) { + {"grant", "http://127.0.0.1/private-token", "denied_destination", policy.Client().Transport}, + {"DNS", "https://missing.example/private-token", "dns", policy.Client().Transport}, + {"timeout", "https://source.example/private-token", "timeout", collectorTransport(func(*http.Request) (*http.Response, error) { return nil, context.DeadlineExceeded })}, + {"redirect", "https://source.example/private-token", "invalid_redirect", collectorTransport(func(*http.Request) (*http.Response, error) { response := collectorResponse(302, "") response.Header = http.Header{"Location": {"https://redirect.example/private-token/%zz"}} return response, nil diff --git a/discovery/shared/metrics.go b/discovery/shared/metrics.go new file mode 100644 index 0000000..22e8560 --- /dev/null +++ b/discovery/shared/metrics.go @@ -0,0 +1,40 @@ +package shared + +import ( + "strconv" + + "github.com/livepeer/node/internal/observability" +) + +// CollectMetrics includes configured sources that have never succeeded and +// sources whose inventory has been evicted. Labels never contain source URLs. +func (c *Collector[R]) CollectMetrics(emit observability.Emit) { + c.mu.Lock() + defer c.mu.Unlock() + for index, source := range c.sources { + labels := observability.Labels{"source_index": strconv.Itoa(index)} + state := "healthy" + if source.QueriedAt.IsZero() { + state = "uninitialized" + if !source.LastSuccess.IsZero() { + state = "evicted" + } + } else if source.Failures > 0 { + state = "retained" + } + for _, candidate := range []string{"healthy", "uninitialized", "evicted", "retained"} { + emit("discovery_source_state", observability.Bool(state == candidate), labels.With("state", candidate)) + } + emit("discovery_source_failures", float64(source.Failures), labels) + last := 0.0 + if !source.LastSuccess.IsZero() { + last = float64(source.LastSuccess.Unix()) + } + emit("discovery_last_success_timestamp_seconds", last, labels) + count := 0 + for _, entry := range source.Entries { + count += len(entry.Runners) + } + emit("discovery_cached_runners", float64(count), labels) + } +} diff --git a/docs/README.md b/docs/README.md index 3bdc3a3..2be7974 100644 --- a/docs/README.md +++ b/docs/README.md @@ -13,6 +13,7 @@ Start with [installation](../README.md#install) and the | [Signer](signer.md) | Configure price limits, authorization, discovery, and Kafka accounting. | | [Chain commands](chain.md) | Inspect accounts, manage stake and funds, and submit transactions. | | [Payment recovery](payment-recovery.md) | Back up state, upgrade or roll back, and recover accounting/redemption work. | +| [Metrics and events](metrics.md) | Scrape app/runner metrics, investigate payments, and configure operational alerts. | ## Developing and integrating diff --git a/docs/configuration.md b/docs/configuration.md index 2b9c7fe..8342a96 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -157,7 +157,5 @@ curl -fsS http://127.0.0.1:8940/readyz ``` All metrics listeners serve `/healthz`, `/readyz`, and `/metrics`. -Orchestrator and discovery readiness report that their listeners are running; -they do not check runner health, upstream availability, or payment dependencies. -Signer readiness checks its payment dependencies and, when enabled, local -accounting storage. See the component guides for those checks. +See [metrics and operational events](metrics.md) for readiness requirements, +scrape configuration, measurements, and query/alert examples. diff --git a/docs/discovery.md b/docs/discovery.md index 4e088fe..01d3476 100644 --- a/docs/discovery.md +++ b/docs/discovery.md @@ -51,8 +51,10 @@ omits the metadata entry or runner entries, respectively. Disabling both returns signers reject responses larger than 1 MiB. The loopback metrics listener defaults to `127.0.0.1:8940` and serves `/healthz`, -`/readyz`, and `/metrics` (`livepeer_discovery_up`). Readiness indicates that the -service is running, even with no available sources. The cache is not persisted. +`/readyz`, and `/metrics`, including source health, cached inventory, refresh +results, and `livepeer_discovery_up`. See [metrics and events](metrics.md). +Readiness indicates that the service is running, even with no available sources. +The cache is not persisted. ## Connect a signer diff --git a/docs/metrics.md b/docs/metrics.md new file mode 100644 index 0000000..67c4ae8 --- /dev/null +++ b/docs/metrics.md @@ -0,0 +1,190 @@ +# Metrics and operational events + +Scrape `/metrics` on each component's existing loopback `MetricsListen`: + +```yaml +scrape_configs: + - job_name: livepeer-orchestrator + scrape_interval: 15s + static_configs: + - targets: ['127.0.0.1:8936'] + - job_name: livepeer-signer + scrape_interval: 15s + static_configs: + - targets: ['127.0.0.1:8938'] + - job_name: livepeer-discovery + scrape_interval: 15s + static_configs: + - targets: ['127.0.0.1:8940'] +``` + +Attach environment/deployment labels in your collector. Scrapes use memory and +local SQLite reads with a one-second deadline; they never call dependencies. +Failed collectors omit unavailable statistics and report +`livepeer_collector_healthy{collector="redemptions"}=0` or +`livepeer_signer_kafka_outbox_healthy=0`. Missing values do not mean zero work. + +## Identity and counting + +New Livepeer families carry `component`; legacy and Go/process collectors retain +their existing labels. App/runner labels use registered `app`, `runner_id`, and +`mode`; aggregate runners for app totals. Sessions and Trickle retain ownership. +Inventory exists before traffic; unregister/expiry removes it, retaining counters. + +Counters reset on restart; durable queue gauges recover from SQLite. ETH values +are approximate operational measurements. Legacy aggregate runner/session, up, +and outbox names remain available. + +Operations use route patterns or fixed names; unknown routes/methods use +`unknown`/`other`. Unregistered identities and request-supplied paths, URLs, +credentials, session IDs, error text, or signer app strings never create labels. +Discovery source indices refer to the current configured list order. + +HTTP requests and app calls count once at completion. Reservations, upstream +attempts, and payment operations count independently; aliases share these paths. +Admission rejection for a known application counts a call without an upstream +attempt. Refresh counts once; charge excludes fixed-session and zero-unit no-ops. + +App/payment outcomes follow causes independently of HTTP status. Funding/policy +rejection, capacity, challenges, refresh (480), no-payment-needed (482), client +cancellation, and intentional session termination are distinct from service +failures (`error`, `transport_error`, `stream_error`). + +Final-header histograms exclude provisional headers and update immediately; +transfer bytes also update during open streams. Lifetime histograms wait for +completion. Failures after HTTP 200/101 remain visible in the terminal outcome; +status zero means no final response was observed before abort. + +HTTP byte counts cover bodies; upgraded connection counts may include framing. +Uploads use `http`; responses use `http`/`sse`; Trickle and upgrades use their +protocol in both directions. +Application success means observed HTTP/transport success. Payload failures, +inference latency, FPS, and GPU use require runner telemetry. + +Redemption transitions/errors follow committed changes, including asynchronous +callbacks and sibling recovery. No-op reconciliation/replay adds no observations; +reorg retries are not service failures, and inclusion is not final settlement. + +## Metric families + +Names below have the `livepeer_` prefix. `_total` denotes counters; durations +are histograms with `_bucket`, `_sum`, and `_count` samples. Other families are +gauges; timestamps use Unix seconds. Most event families appear on first use. + +| Area | Families and dimensions | +| --- | --- | +| Runtime | `build_info{version,revision}`, standard `go_*`, `process_*`, and `go_build_info`. | +| Legacy | `runners`, `sessions`, `signer_up`, and `discovery_up` retain their existing labels. | +| HTTP | `http_requests_total{operation,method,status}`, `http_request_duration_seconds{operation,method}`, `http_requests_in_flight`, `http_admission_rejections_total{pool}`. Probe/scrape requests are excluded. | +| Apps | `app_calls_total{app,runner_id,mode,protocol,outcome}`, `app_call_duration_seconds`, `app_response_header_duration_seconds`, `app_calls_in_flight`. Histograms use identity/protocol; in-flight uses identity. | +| Upstreams | `upstream_requests_total{app,runner_id,mode,destination,outcome}`, `upstream_response_header_duration_seconds`. Destination is `runner` or `session_proxy`; HTTP failures use `http_4xx`/`http_5xx`. | +| Inventory | `runner_registered`, `runner_ready`, `runner_capacity`, `runner_capacity_available`, `runner_sessions{state="pending\|active"}`, `runner_last_heartbeat_timestamp_seconds`, all with app identity. Unavailable runners expose zero available capacity; heartbeat timestamps apply to dynamic runners. | +| Lifecycle | `runner_events_total{event}`, `runner_health_checks_total{outcome}`, `session_reservations_total{outcome}`, `session_ends_total{reason}`, `session_duration_seconds`, with app identity. Reservations include allocations pending payment; only activated sessions contribute lifetime observations. | +| Streams | `trickle_channels{kind="control\|session"}`, `trickle_buffered_bytes` for retained published segment bytes; `stream_transfer_bytes_total{app,runner_id,mode,protocol,direction}`, `stream_errors_total{app,runner_id,mode,protocol,outcome}`. Trickle requests are transport activity, not extra app invocations. | +| Payments | `payment_operations_total{operation,outcome}` for challenge/receive/refresh/charge; `payment_tickets_total{kind="accepted\|winning"}`, `payment_credit_eth_total`, `payment_charge_eth_total`, `payment_billed_seconds_total`, `payment_fixed_charges_total`, with app identity. Credit is accepted expected ticket value; charges are successfully debited service usage. | +| Signer | `signer_payments_total{type,outcome}`, `signer_tickets_total{type}`, `signer_sign_operations_total{kind,outcome}`. Signing kinds are ticket, segment, state, and orchestrator_info. Partial signing before a failed request remains visible. Successful payment/ticket totals follow required outbox persistence, even if response delivery is interrupted. | +| Authorization | `signer_auth_webhook_requests_total{status,outcome}`, `signer_auth_webhook_duration_seconds`, `signer_auth_cache_hits_total`. Status zero means no webhook response; outcomes distinguish success, denied, and error. | +| Outbox | Existing `signer_kafka_pending_events`, `signer_kafka_pending_bytes`, `signer_kafka_oldest_event_age_seconds`, `signer_kafka_outbox_healthy`, `signer_kafka_publish_errors_total`, `signer_kafka_enqueue_errors_total`, and `signer_kafka_storage_errors_total`. New `signer_kafka_delivered_events_total` and `signer_kafka_last_delivery_timestamp_seconds` follow successful local acknowledgement; delivery remains at least once. | +| Redemption queue | `redemption_queue_tickets{state}`, `redemption_oldest_ticket_timestamp_seconds{state}`: safe parameter-expiry `waiting`, clock-eligible `eligible`, `in_flight`, `awaiting_finality`, or `unknown` without a fresh clock observation. Each ticket counts once, regardless of replacements. | +| Transactions | `redemption_unresolved_transactions{phase}`, `redemption_oldest_transaction_timestamp_seconds{phase}` include historical retries/replacements until the identity is confirmed, reverted, or superseded, or its ticket is settled (`confirmed`/`used`). Ticket expiry or invalidation alone does not remove an unresolved identity. `sending` appears as `broadcast`. | +| Redemption activity | `redemption_transitions_total{event}`, `redemption_broadcasts_total{outcome}`, `redemption_errors_total{error_kind}`, `redemption_settlements_total`, `redemption_settled_eth_total`, `redemption_settlement_duration_seconds`, `redemption_last_settlement_timestamp_seconds`, `redemption_last_success_timestamp_seconds`, `redemption_worker_last_completed_timestamp_seconds`. Settlement counts once per ticket, including `used` → `confirmed` upgrades. | +| Chain/pricing | `rpc_requests_total{method,outcome}`, `rpc_request_duration_seconds{method}` include direct contract calls and JSON-RPC errors over HTTP 200. `chain_snapshot_block`, `chain_snapshot_round`, `chain_snapshot_last_success_timestamp_seconds`, `price_feed_updates_total{outcome}`, `price_feed_valid_until_timestamp_seconds`, `dependency_healthy{dependency}`, `signer_deposit_eth`, `signer_reserve_eth`, `redeemer_gas_balance_eth`. Block uses the protocol L1 clock; signer reserve is total reserve observed by readiness. | +| Discovery | `discovery_refreshes_total{source_index,outcome}`, `discovery_refresh_duration_seconds{source_index}`, `discovery_source_state{source_index,state}`, `discovery_source_failures{source_index}`, `discovery_cached_runners{source_index}`, `discovery_last_success_timestamp_seconds{source_index}`. States distinguish healthy, retained, uninitialized, and evicted sources. | + +Empty queues have zero counts/oldest timestamps. Fixed exchange rates have a +validity timestamp of zero. Chain/fund gauges retain the last observation; +check snapshot freshness and dependency health alongside them. + +## Queries and starting alerts + +Calls per second and app service-failure ratio: + +```promql +sum by (app, runner_id) (rate(livepeer_app_calls_total[5m])) + +sum by (app) (rate(livepeer_app_calls_total{outcome=~"error|transport_error|stream_error"}[5m])) +/ +clamp_min(sum by (app) (rate(livepeer_app_calls_total[5m])), 0.001) +``` + +Start with a warning above 5% for ten minutes, gated on meaningful traffic. +Client cancellations and payment challenges are excluded from the numerator. + +App p95 final-header latency and available capacity: + +```promql +histogram_quantile(0.95, + sum by (app, le) (rate(livepeer_app_response_header_duration_seconds_bucket[5m]))) + +sum by (app) (livepeer_runner_capacity_available) +``` + +Choose latency thresholds per workload. Warn on zero capacity together with +increasing reservation/admission rejections for five minutes; idle apps need +not alert solely for zero capacity. + +Payment charges and accepted/winning tickets per second: + +```promql +sum by (app, runner_id) (rate(livepeer_payment_charge_eth_total[5m])) + +sum by (app, kind) (rate(livepeer_payment_tickets_total[5m])) +``` + +Eligible queue age and unresolved transaction age: + +```promql +(time() - livepeer_redemption_oldest_ticket_timestamp_seconds{state="eligible"}) > 600 +and on (job, instance, state) +livepeer_redemption_queue_tickets{state="eligible"} > 0 + +(time() - livepeer_redemption_oldest_transaction_timestamp_seconds) > 900 +and on (job, instance, phase) +livepeer_redemption_unresolved_transactions > 0 +``` + +Use a ten-minute persistence window for eligible backlog. Parameter-expiry +waiting does not qualify. Tune transaction thresholds above +`RedeemerTxTimeout × (1 + RedeemerMaxTxReplacements)` plus expected finality time. +An error-free pass updates `redemption_last_success_timestamp_seconds`; it is +not proof of settlement progress. Compare worker/pass freshness with queue age, +transaction phase, and `redemption_last_settlement_timestamp_seconds`. + +Other useful starting conditions: + +- Failed collectors/dependencies or stale worker completion for one minute, + allowing for the configured heartbeat cadence. +- Positive feed validity timestamp earlier than `time()` when paid traffic is + expected; fixed-rate deployments use zero. +- Outbox age above five minutes with pending events, or publish failures with + growing pending bytes. Storage failure/full capacity is more urgent because + it withholds payment. +- Zero redeemer gas balance or low signer deposit/reserve. Choose funding + thresholds from actual redemption fees and payment exposure. +- Discovery sources retained/evicted beyond the expected refresh interval. + Successful empty inventories remain valid observations. + +## Readiness, migration, and logs + +`/healthz` checks liveness. Paid orchestrator `/readyz` requires writable payment +storage, chain access, an active recipient, valid pricing, and worker completion. +Checks run at heartbeat cadence even with empty queues. Dependency observations +and worker completion expire after `max(60 seconds, 3 × HeartbeatInterval)`; +queue stalls and individual ticket errors remain separate signals. +Off-chain orchestrator/discovery readiness reports listener health. +Signer readiness requires chain access, positive deposit/total reserve, no +withdrawal through the next round, fresh pricing, and healthy enabled outbox +storage with capacity. Kafka connectivity alone is not required; recipient +claimable reserve is checked when generating payments. + +Migration 003 adds enqueue time. Existing rows receive migration time, so their +ages are lower bounds. New timestamps survive restarts. Rolling back 003 drops +only enqueue times; another upgrade restarts those historical measurements. +Follow [payment recovery](payment-recovery.md) before schema changes. + +Operational logs retain their encoding and use fixed component/event/operation, +outcome, and error-kind fields, with app/runner/session/transaction correlation +where relevant. Remote, key, and storage error text is replaced with safe +classifications. Raw URLs, bodies, headers, credentials, signatures, randomness, +and signed transaction bytes are excluded. Routine segment progress is debug +level. diff --git a/docs/orchestrator.md b/docs/orchestrator.md index aae6be9..622793d 100644 --- a/docs/orchestrator.md +++ b/docs/orchestrator.md @@ -133,6 +133,10 @@ See [payment recovery](payment-recovery.md) for backup and reconciliation. ## Resource limits +Paid `/readyz` returns 503 until payment dependencies and the redemption worker +are ready. See [metrics and operational events](metrics.md) for requirements, +app/runner measurements, queue monitoring, and scrape/query examples. + The registry accepts up to 256 runners and 10,000 sessions, with 25 generated proxies per session. Control requests have 64 admission slots and a five-second body deadline. Streaming requests have 256 separate slots. diff --git a/docs/signer.md b/docs/signer.md index 552485e..f69803a 100644 --- a/docs/signer.md +++ b/docs/signer.md @@ -203,22 +203,10 @@ curl -fsS http://127.0.0.1:8938/healthz curl -fsS http://127.0.0.1:8938/metrics ``` -`/healthz` checks liveness. `/readyz` requires chain access, positive deposit and -total reserve, no withdrawal scheduled at or before the next round, a fresh -exchange rate, and healthy enabled outbox storage with capacity. Kafka -connectivity alone does not affect readiness. Recipient-specific claimable -reserve is checked during payment generation. - -Monitor backlog, errors, and filesystem space. `/metrics` exposes: - -- `livepeer_signer_up` -- `livepeer_signer_kafka_pending_events` -- `livepeer_signer_kafka_pending_bytes` -- `livepeer_signer_kafka_oldest_event_age_seconds` -- `livepeer_signer_kafka_outbox_healthy` -- `livepeer_signer_kafka_publish_errors_total` -- `livepeer_signer_kafka_enqueue_errors_total` -- `livepeer_signer_kafka_storage_errors_total` +See [metrics and operational events](metrics.md) for readiness requirements, +metric definitions, and query/alert examples. + +Monitor backlog, errors, and filesystem space. Replicas with the same key and authorization configuration can continue client-held signed state. Keep a separate durable outbox for each replica. diff --git a/eth/rpc.go b/eth/rpc.go index 117060f..36ad348 100644 --- a/eth/rpc.go +++ b/eth/rpc.go @@ -3,6 +3,7 @@ package eth import ( "bytes" "context" + "encoding/json" "errors" "fmt" "io" @@ -27,8 +28,13 @@ const maxRPCResponse = 1 << 20 type RPC struct { ethereum *ethclient.Client http *http.Client + observer func(string, time.Duration, error) } +// SetObserver installs a hook before the client is used. Observations contain +// allowlisted methods and redacted errors, never RPC payloads or URLs. +func (r *RPC) SetObserver(observer func(string, time.Duration, error)) { r.observer = observer } + func OpenRPC(endpoint string) (*RPC, error) { u, err := destination.ParseURL(endpoint) if err != nil { @@ -46,14 +52,16 @@ func NewRPC(endpoint *url.URL, transport http.RoundTripper) (*RPC, error) { if transport == nil { transport = http.DefaultTransport.(*http.Transport).Clone() } - client := &http.Client{Transport: boundedRPCTransport{transport}, Timeout: 15 * time.Second} + r := new(RPC) + client := &http.Client{Transport: boundedRPCTransport{transport, r}, Timeout: 15 * time.Second} // Redirects can replay eth_sendRawTransaction POST bodies. client.CheckRedirect = func(*http.Request, []*http.Request) error { return http.ErrUseLastResponse } rpc, err := gethrpc.DialOptions(context.Background(), endpoint.String(), gethrpc.WithHTTPClient(client)) if err != nil { return nil, errors.New("invalid Ethereum RPC endpoint") } - return &RPC{ethereum: ethclient.NewClient(rpc), http: client}, nil + r.ethereum, r.http = ethclient.NewClient(rpc), client + return r, nil } func (r *RPC) Close() { @@ -64,10 +72,38 @@ func (r *RPC) Close() { var errRPCResponseLimit = errors.New("ethereum RPC response exceeds 1 MiB") // Bound the HTTP body before geth decodes it or includes it in an HTTP error. -type boundedRPCTransport struct{ http.RoundTripper } - -func (t boundedRPCTransport) RoundTrip(request *http.Request) (*http.Response, error) { - response, err := t.RoundTripper.RoundTrip(request) +type boundedRPCTransport struct { + http.RoundTripper + rpc *RPC +} + +func (t boundedRPCTransport) RoundTrip(request *http.Request) (response *http.Response, err error) { + observer := t.rpc.observer + var observed error + if observer != nil { + start, method := time.Now(), "unknown" + if request.GetBody != nil { + if body, err := request.GetBody(); err == nil { + var envelope struct { + Method string `json:"method"` + } + if json.NewDecoder(body).Decode(&envelope) == nil { + switch envelope.Method { + case "eth_chainId", "eth_call", "eth_getCode", "eth_blockNumber", "eth_getBalance", "eth_getTransactionCount", "eth_getTransactionReceipt", "eth_getTransactionByHash", "eth_getBlockByNumber", "eth_estimateGas", "eth_sendRawTransaction", "eth_maxPriorityFeePerGas", "eth_gasPrice": + method = envelope.Method + } + } + _ = body.Close() + } + } + defer func() { + if err != nil { + observed = err + } + observer(method, time.Since(start), safeRPCError(observed)) + }() + } + response, err = t.RoundTripper.RoundTrip(request) if err != nil { return nil, err } @@ -79,6 +115,16 @@ func (t boundedRPCTransport) RoundTrip(request *http.Request) (*http.Response, e if len(data) > maxRPCResponse { return nil, errRPCResponseLimit } + if observer != nil { + var envelope struct { + Error *struct { + Code int `json:"code"` + } `json:"error"` + } + if response.StatusCode < 200 || response.StatusCode >= 300 || json.Unmarshal(data, &envelope) != nil || envelope.Error != nil { + observed = errors.New("ethereum RPC request failed") + } + } response.Body = io.NopCloser(bytes.NewReader(data)) return response, nil } diff --git a/eth/rpc_test.go b/eth/rpc_test.go index d9f554d..e29bf5b 100644 --- a/eth/rpc_test.go +++ b/eth/rpc_test.go @@ -9,6 +9,7 @@ import ( "net/http/httptest" "net/url" "testing" + "time" "github.com/stretchr/testify/require" ) @@ -46,7 +47,17 @@ func TestRPCTransportPolicy(t *testing.T) { rpc, err := NewRPC(parsed, nil) require.NoError(t, err) defer rpc.Close() + observed := 0 + rpc.SetObserver(func(method string, elapsed time.Duration, observedErr error) { + observed++ + require.Equal(t, "eth_chainId", method) + require.GreaterOrEqual(t, elapsed, time.Duration(0)) + require.Error(t, observedErr) + require.NotContains(t, observedErr.Error(), "secret-") + }) _, err = rpc.ChainID(t.Context()) + require.Equal(t, 1, observed) + require.ErrorContains(t, err, tc.error) require.NotContains(t, err.Error(), "secret-password") require.NotContains(t, err.Error(), "secret-token") diff --git a/go.mod b/go.mod index 40e72a0..13817bb 100644 --- a/go.mod +++ b/go.mod @@ -5,11 +5,13 @@ go 1.27.3 require ( github.com/BurntSushi/toml v1.6.0 github.com/ethereum/go-ethereum v1.17.8 + github.com/felixge/httpsnoop v1.1.0 github.com/google/uuid v1.6.0 github.com/gorilla/websocket v1.5.3 github.com/holiman/uint256 v1.3.2 github.com/j0sh/boa v1.0.2 github.com/j0sh/minikafka v0.0.0-20261001174935-0bc8dcedd322 + github.com/prometheus/client_golang v1.25.0 github.com/segmentio/kafka-go v0.4.51 github.com/spf13/cobra v1.10.2 github.com/stretchr/testify v1.12.1 @@ -21,6 +23,7 @@ require ( github.com/Microsoft/go-winio v0.6.2 // indirect github.com/ProjectZKM/Ziren/crates/go-runtime/zkvm_runtime v0.0.0-20251001021608-1fe7b43fc4d6 // indirect github.com/StackExchange/wmi v1.2.1 // indirect + github.com/beorn7/perks v1.0.1 // indirect github.com/bits-and-blooms/bitset v1.20.0 // indirect github.com/cespare/xxhash/v2 v2.3.0 // indirect github.com/consensys/gnark-crypto v0.18.1 // indirect @@ -35,10 +38,14 @@ require ( github.com/go-logr/stdr v1.2.2 // indirect github.com/go-ole/go-ole v1.3.0 // indirect github.com/inconshreveable/mousetrap v1.1.0 // indirect - github.com/klauspost/compress v1.18.7 // indirect + github.com/klauspost/compress v1.20.1 // indirect github.com/mattn/go-isatty v0.0.24 // indirect + github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect github.com/ncruces/go-strftime v1.0.0 // indirect github.com/pierrec/lz4/v4 v4.1.26 // indirect + github.com/prometheus/client_model v0.6.3 // indirect + github.com/prometheus/common v0.72.0 // indirect + github.com/prometheus/procfs v0.22.0 // indirect github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec // indirect github.com/shirou/gopsutil v3.21.4-0.20210419000835-c7a38de76ee5+incompatible // indirect github.com/spf13/pflag v1.0.10 // indirect @@ -58,7 +65,7 @@ require ( golang.org/x/exp v0.0.0-20250620022241-b7579e27df2b // indirect golang.org/x/sync v0.23.0 // indirect golang.org/x/sys v0.48.0 // indirect - golang.org/x/text v0.41.0 // indirect + golang.org/x/text v0.42.0 // indirect modernc.org/libc v1.77.1 // indirect modernc.org/mathutil v1.7.1 // indirect modernc.org/memory v1.12.1 // indirect diff --git a/go.sum b/go.sum index 2d38c38..fb1166a 100644 --- a/go.sum +++ b/go.sum @@ -68,6 +68,8 @@ github.com/ethereum/go-bigmodexpfix v0.0.0-20250911101455-f9e208c548ab h1:rvv6MJ github.com/ethereum/go-bigmodexpfix v0.0.0-20250911101455-f9e208c548ab/go.mod h1:IuLm4IsPipXKF7CW5Lzf68PIbZ5yl7FFd74l/E0o9A8= github.com/ethereum/go-ethereum v1.17.8 h1:iKuXrT38t1PaU6aBw6MjBJhGoCl/+Ir0vf5aqQhYT38= github.com/ethereum/go-ethereum v1.17.8/go.mod h1:Iui379BD7ryQSFeIDn3sh9Od2I1uheqJD2/6N0m4xm0= +github.com/felixge/httpsnoop v1.1.0 h1:3YtUj32ZZkqZtt3sZZsClsymw/QDuVfpNhoA31zeORc= +github.com/felixge/httpsnoop v1.1.0/go.mod h1:Zqxgdd+1Rkcz8euOqdr7lqgCRJztwr5hp9vDSi5UZCE= github.com/ferranbt/fastssz v0.1.4 h1:OCDB+dYDEQDvAgtAGnTSidK1Pe2tW3nFV40XyMkTeDY= github.com/ferranbt/fastssz v0.1.4/go.mod h1:Ea3+oeoRGGLGm5shYAeDgu6PGUlcvQhE2fILyD9+tGg= github.com/fjl/jsonw v0.1.0 h1:V3MyR79fjLpn/+bMgvegdGUIhoJOzjmqWcKDgcOmY1I= @@ -92,8 +94,6 @@ github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q= github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q= github.com/golang-jwt/jwt/v4 v4.5.2 h1:YtQM7lnr8iZ+j5q71MGKkNw9Mn7AjHM68uc9g5fXeUI= github.com/golang-jwt/jwt/v4 v4.5.2/go.mod h1:m21LjoU+eqJr34lmDMbreY2eSTRJ1cv77w39/MY0Ch0= -github.com/golang/protobuf v1.5.4 h1:i7eJL8qZTpSEXOPTxNKhASYpMn+8e5Q6AdndVa1dWek= -github.com/golang/protobuf v1.5.4/go.mod h1:lnTiLA8Wa4RWRcIUkrtSVa5nRhsEGBg48fD6rSs7xps= github.com/golang/snappy v1.0.1-0.20260716114414-9ae09f520e93 h1:GpQQr4L8jsBtJSURCDqQboOdgpVMU6vR9REjc8nR4Qc= github.com/golang/snappy v1.0.1-0.20260716114414-9ae09f520e93/go.mod h1:/XxbfmMg8lxefKM7IXC3fBNl/7bRcc72aCRzEWrmP2Q= github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= @@ -138,8 +138,8 @@ github.com/j0sh/minikafka v0.0.0-20261001174935-0bc8dcedd322 h1:CmfMHAslXpaf1zol github.com/j0sh/minikafka v0.0.0-20261001174935-0bc8dcedd322/go.mod h1:akLKEMvm/CLxdF3C07jwUvdwYt1tRjXds1vlRY+XrOE= github.com/jackpal/go-nat-pmp v1.0.2 h1:KzKSgb7qkJvOUTqYl9/Hg/me3pWgBmERKrTGD7BdWus= github.com/jackpal/go-nat-pmp v1.0.2/go.mod h1:QPH045xvCAeXUZOxsnwmrtiCoxIr9eob+4orBN1SBKc= -github.com/klauspost/compress v1.18.7 h1:aUyZsS4kH3QTKurYhAOwAHxllVPnOthb3vPfnF1Ehjw= -github.com/klauspost/compress v1.18.7/go.mod h1:cwPg85FWrGar70rWktvGQj8/hthj3wpl0PGDogxkrSQ= +github.com/klauspost/compress v1.20.1 h1:T7kKElXUMXrUJ2E9QhQhxFtcK5rPyLdsGZvdbLMPdiQ= +github.com/klauspost/compress v1.20.1/go.mod h1:LUdAzn7YLVvxLpc7y3V1m40wESHTgc1422pwwBSKYuI= github.com/klauspost/cpuid/v2 v2.0.9 h1:lgaqFMSdTdQYdZ04uHyN2d/eKdOMyi2YLSvlQIBFYa4= github.com/klauspost/cpuid/v2 v2.0.9/go.mod h1:FInQzS24/EEf25PyTYn52gqo7WaD8xa0213Md/qVLRg= github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= @@ -158,8 +158,6 @@ github.com/mattn/go-runewidth v0.0.13 h1:lTGmDsbAYt5DmK6OnoV7EuIF1wEIFAcxld6ypU4 github.com/mattn/go-runewidth v0.0.13/go.mod h1:Jdepj2loyihRzMpdS35Xk/zdY8IAYHsh153qUoGf23w= github.com/mattn/go-sqlite3 v1.14.18 h1:JL0eqdCOq6DJVNPSvArO/bIV9/P7fbGrV00LZHc+5aI= github.com/mattn/go-sqlite3 v1.14.18/go.mod h1:2eHXhiwb8IkHr+BDWZGa96P6+rkvnG63S2DGjv9HUNg= -github.com/matttproud/golang_protobuf_extensions v1.0.4 h1:mmDVorXM7PCGKw94cs5zkfA9PSy5pEvNWRP0ET0TIVo= -github.com/matttproud/golang_protobuf_extensions v1.0.4/go.mod h1:BSXmuO+STAnVfrANrmjBb36TMTDstsz7MSK+HVaYKv4= github.com/minio/minlz v1.0.1-0.20250507153514-87eb42fe8882 h1:0lgqHvJWHLGW5TuObJrfyEi6+ASTKDBWikGvPqy9Yiw= github.com/minio/minlz v1.0.1-0.20250507153514-87eb42fe8882/go.mod h1:qT0aEB35q79LLornSzeDH75LBf3aH1MV+jB5w9Wasec= github.com/minio/sha256-simd v1.0.0 h1:v1ta+49hkWZyvaKwrQB8elexRqm6Y0aMLjCNsrYxo6g= @@ -168,6 +166,8 @@ github.com/mitchellh/mapstructure v1.4.1 h1:CpVNEelQCZBooIPDn+AR3NpivK/TIKU8bDxd github.com/mitchellh/mapstructure v1.4.1/go.mod h1:bFUtVrKA4DC2yAKiSyO/QUcy7e+RRV2QTWOzhPopBRo= github.com/mitchellh/pointerstructure v1.2.0 h1:O+i9nHnXS3l/9Wu7r4NrEdwA2VFTicjUEN1uBnDo34A= github.com/mitchellh/pointerstructure v1.2.0/go.mod h1:BRAsLI5zgXmw97Lf6s25bs8ohIXc3tViBH44KcwB2g4= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= github.com/ncruces/go-strftime v1.0.0 h1:HMFp8mLCTPp341M/ZnA4qaf7ZlsbTc+miZjCLOFAw7w= github.com/ncruces/go-strftime v1.0.0/go.mod h1:Fwc5htZGVVkseilnfgOVb9mKy6w1naJmn9CehxcKcls= github.com/opentracing/opentracing-go v1.1.0 h1:pWlfV3Bxv7k65HYwkikxat0+s3pV4bsqf19k25Ur8rU= @@ -186,14 +186,14 @@ github.com/pion/transport/v4 v4.1.0 h1:8S+nF2reM2cJuqC6g78OVy2BBgmbdns+acx3jA97B github.com/pion/transport/v4 v4.1.0/go.mod h1:06hFI+jCFcok2X2MekVufNZ/uzNZXivGBPfviSVcjgM= github.com/pkg/errors v0.9.1 h1:FEBLx1zS214owpjy7qsBeixbURkuhQAwrK5UwLGTwt4= github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= -github.com/prometheus/client_golang v1.16.0 h1:yk/hx9hDbrGHovbci4BY+pRMfSuuat626eFsHb7tmT8= -github.com/prometheus/client_golang v1.16.0/go.mod h1:Zsulrv/L9oM40tJ7T815tM89lFEugiJ9HzIqaAx4LKc= -github.com/prometheus/client_model v0.3.0 h1:UBgGFHqYdG/TPFD1B1ogZywDqEkwp3fBMvqdiQ7Xew4= -github.com/prometheus/client_model v0.3.0/go.mod h1:LDGWKZIo7rky3hgvBe+caln+Dr3dPggB5dvjtD7w9+w= -github.com/prometheus/common v0.42.0 h1:EKsfXEYo4JpWMHH5cg+KOUWeuJSov1Id8zGR8eeI1YM= -github.com/prometheus/common v0.42.0/go.mod h1:xBwqVerjNdUDjgODMpudtOMwlOwf2SaTr1yjz4b7Zbc= -github.com/prometheus/procfs v0.10.1 h1:kYK1Va/YMlutzCGazswoHKo//tZVlFpKYh+PymziUAg= -github.com/prometheus/procfs v0.10.1/go.mod h1:nwNm2aOCAYw8uTR/9bWRREkZFxAUcWzPHWJq+XBB/FM= +github.com/prometheus/client_golang v1.25.0 h1:cDtW1TcFsMi1RJc8khwCKB4VhzwV04aKqbYtNOXuiK0= +github.com/prometheus/client_golang v1.25.0/go.mod h1:j2X/4/kaQHLPnmyEU8zjmkndo1T317VpCIQEml8LTKk= +github.com/prometheus/client_model v0.6.3 h1:O0jaTVAYNxTHYInEPFJt5I3+sN8zqBtVMPTB1qyxiEo= +github.com/prometheus/client_model v0.6.3/go.mod h1:gpN5P9S7Rr6Yr92PiQ+Ixvhf6JZEkF1dnxsYL2aPBEM= +github.com/prometheus/common v0.72.0 h1:tAYsE+sPJxIncDAobm4H5aQjmox9ZxEIIqPbiffa8G4= +github.com/prometheus/common v0.72.0/go.mod h1:77NWqAQ2tXT7BIK40qjJdw5Acrsrg1TlHAnsQi3i6mk= +github.com/prometheus/procfs v0.22.0 h1:6q9+/JL9IKAPbCmBrv9n5O5Ty3NKnciV5X7YGw0oics= +github.com/prometheus/procfs v0.22.0/go.mod h1:CvmFr/GVhIjIvWJZW3tgkODBQMRIf0EyWMQLHCHab58= github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec h1:W09IVJc94icq4NjY3clb7Lk8O1qJ8BdBEF8z0ibU0rE= github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec/go.mod h1:qqbHyh8v60DhA7CoWK5oRCqLrMHRGoxYCSS9EjAz6Eo= github.com/rivo/uniseg v0.2.0 h1:S1pD9weZBuJdFmowNwbpi7BJ8TNftyUImj/0WQi72jY= @@ -250,6 +250,10 @@ go.opentelemetry.io/otel/sdk v1.46.0 h1:h5CNQQjEbuQXY/JfZtgt3i7HVFV3aHPO2OAwO2eT go.opentelemetry.io/otel/sdk v1.46.0/go.mod h1:GAERFXFt5SYCEB+YiKUbMBeza6UaDH7GmGOZEfh2gSM= go.opentelemetry.io/otel/trace v1.46.0 h1:OULy7ccdJnZtJ0UDYFOIGaCmiWzJ8Vi2G/Rsu60qs1c= go.opentelemetry.io/otel/trace v1.46.0/go.mod h1:J7GAXweO77XSFkB/rmAqk9D6ihszhFjLU+d9WuUxDLI= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.yaml.in/yaml/v2 v2.4.4 h1:tuyd0P+2Ont/d6e2rl3be67goVK4R6deVxCUX5vyPaQ= +go.yaml.in/yaml/v2 v2.4.4/go.mod h1:gMZqIpDtDqOfM0uNfy0SkpRhvUryYH0Z6wdMYcacYXQ= go.yaml.in/yaml/v3 v3.0.4/go.mod h1:DhzuOOF2ATzADvBadXxruRBLzYTpT36CKvDb3+aBEFg= go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= @@ -265,8 +269,8 @@ golang.org/x/mod v0.41.0/go.mod h1:Ek9pY8RKWXwsWvd3rQiHYtMqkjSUV+s1Rj7j4H5Ur6o= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= golang.org/x/net v0.0.0-20210226172049-e18ecbb05110/go.mod h1:m0MpNAwzfU5UDzcl9v0D8zg8gWTRqZa9RBIspLL5mdg= golang.org/x/net v0.0.0-20220722155237-a158d28d115b/go.mod h1:XRhObCWvk6IyKnWLug+ECip1KBveYUHfp+8e9klMJ9c= -golang.org/x/net v0.58.0 h1:ynWG7rqYi4ccpTEuPZ2QGWHktVEM9DMCj9yzDE0Q7To= -golang.org/x/net v0.58.0/go.mod h1:YwCddHnFlT7eLQqVprV19OnhLGtc5xOKgE0RyqgfWAU= +golang.org/x/net v0.59.0 h1:5zfYln+w5XCxwrnMMJPufRgNoXEaGxl0wo5GqPXyues= +golang.org/x/net v0.59.0/go.mod h1:2DA/G1UfVbCpQPeWTmMPGY7Cs2PkBkwu743bVX5PIVg= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20220722155255-886fb9371eb4/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.23.0 h1:KameEIfc1IkluZyXWLn39Wd4tURc6GbCiISGiZm2bQk= @@ -289,8 +293,8 @@ golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ= golang.org/x/text v0.3.7/go.mod h1:u+2+/6zg+i71rQMx5EYifcz6MCKuco9NR6JIITiCfzQ= golang.org/x/text v0.3.8/go.mod h1:E6s5w1FMmriuDzIBO73fBruAKo1PCIq6d2Q6DHfQ8WQ= -golang.org/x/text v0.41.0 h1:vz/seA0lnX87Othu2f/0L24RcgrXD9/YFTSuGjj3rH8= -golang.org/x/text v0.41.0/go.mod h1:jvf1O8ajNzZqhSrQBPbutR/EB83Cc0CFrezNQIwbb5M= +golang.org/x/text v0.42.0 h1:JbOZXgfeCPU9gacVtYliJqOhD+zhrEqK4LfdpmlUZqI= +golang.org/x/text v0.42.0/go.mod h1:ojzP1Z+2QtioaF8DTtO8K5q7JWVVYwZKenzujK0Zd0E= golang.org/x/time v0.14.0 h1:MRx4UaLrDotUKUdCIqzPC48t1Y9hANFKIRpNx+Te8PI= golang.org/x/time v0.14.0/go.mod h1:eL/Oa2bBBK0TkX57Fyni+NgnyQQN4LitPmob2Hjnqw4= golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ= diff --git a/internal/observability/metrics.go b/internal/observability/metrics.go new file mode 100644 index 0000000..5d21aba --- /dev/null +++ b/internal/observability/metrics.go @@ -0,0 +1,531 @@ +// Package observability supplies process-local Prometheus registries and safe +// transport observations. Labels passed here must come from fixed operations or +// registered inventory, never request paths, credentials, or error messages. +package observability + +import ( + "bufio" + "context" + "encoding/json" + "errors" + "io" + "math/big" + "net" + "net/http" + "sort" + "strconv" + "strings" + "sync" + "sync/atomic" + "syscall" + "time" + + "github.com/felixge/httpsnoop" + "github.com/livepeer/node/cmd/version" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/collectors" + "github.com/prometheus/client_golang/prometheus/promhttp" +) + +type Labels map[string]string + +func (l Labels) With(key, value string) Labels { + copy := make(Labels, len(l)+1) + for k, v := range l { + copy[k] = v + } + copy[key] = value + return copy +} + +type Identity struct{ App, Runner, Mode string } + +func (i Identity) Labels() Labels { + return Labels{"app": i.App, "runner_id": i.Runner, "mode": i.Mode} +} + +// Metrics owns a registry; services and tests never share global collectors. +// Families are registered on first use, with a fixed label schema thereafter. +type Metrics struct { + Registry *prometheus.Registry + Component string + mu sync.Mutex + counters map[string]*prometheus.CounterVec + gauges map[string]*prometheus.GaugeVec + histograms map[string]*prometheus.HistogramVec +} + +func New(component string) *Metrics { + m := &Metrics{Registry: prometheus.NewRegistry(), Component: component, + counters: map[string]*prometheus.CounterVec{}, gauges: map[string]*prometheus.GaugeVec{}, histograms: map[string]*prometheus.HistogramVec{}} + m.Registry.MustRegister(collectors.NewGoCollector(), collectors.NewProcessCollector(collectors.ProcessCollectorOpts{}), collectors.NewBuildInfoCollector()) + m.Gauge("build_info", Labels{"version": version.Version, "revision": version.Commit}).Set(1) + return m +} + +func (m *Metrics) Handler() http.Handler { + return promhttp.HandlerFor(m.Registry, promhttp.HandlerOpts{}) +} + +func labelValues(labels Labels) (keys, values []string) { + for key := range labels { + keys = append(keys, key) + } + sort.Strings(keys) + for _, key := range keys { + values = append(values, labels[key]) + } + return +} + +func metricHelp(name string) string { return strings.ReplaceAll(name, "_", " ") + "." } + +func (m *Metrics) Add(name string, value float64, labels Labels) { + if m == nil { + return + } + m.counter(name, labels).Add(value) +} + +func (m *Metrics) counter(name string, labels Labels) prometheus.Counter { + keys, values := labelValues(labels) + m.mu.Lock() + v := m.counters[name] + if v == nil { + v = prometheus.NewCounterVec(prometheus.CounterOpts{Namespace: "livepeer", Name: name, Help: metricHelp(name), ConstLabels: prometheus.Labels{"component": m.Component}}, keys) + m.Registry.MustRegister(v) + m.counters[name] = v + } + m.mu.Unlock() + return v.WithLabelValues(values...) +} + +func (m *Metrics) Gauge(name string, labels Labels) prometheus.Gauge { + keys, values := labelValues(labels) + m.mu.Lock() + defer m.mu.Unlock() + v := m.gauges[name] + if v == nil { + v = prometheus.NewGaugeVec(prometheus.GaugeOpts{Namespace: "livepeer", Name: name, Help: metricHelp(name), ConstLabels: prometheus.Labels{"component": m.Component}}, keys) + m.Registry.MustRegister(v) + m.gauges[name] = v + } + return v.WithLabelValues(values...) +} + +func (m *Metrics) Observe(name string, value float64, labels Labels) { + if m == nil { + return + } + keys, values := labelValues(labels) + m.mu.Lock() + v := m.histograms[name] + if v == nil { + buckets := []float64{.005, .01, .025, .05, .1, .25, .5, 1, 2.5, 5, 10, 30, 60} + if name == "session_duration_seconds" || name == "app_call_duration_seconds" || name == "redemption_settlement_duration_seconds" { + buckets = []float64{1, 5, 15, 30, 60, 300, 900, 3600, 10800} + } + v = prometheus.NewHistogramVec(prometheus.HistogramOpts{Namespace: "livepeer", Name: name, Help: metricHelp(name), ConstLabels: prometheus.Labels{"component": m.Component}, Buckets: buckets}, keys) + m.Registry.MustRegister(v) + m.histograms[name] = v + } + m.mu.Unlock() + v.WithLabelValues(values...).Observe(value) +} + +type Emit func(name string, value float64, labels Labels) +type snapshotCollector struct { + collect func(Emit) + component string +} + +func (c snapshotCollector) Describe(chan<- *prometheus.Desc) {} +func (c snapshotCollector) Collect(ch chan<- prometheus.Metric) { + c.collect(func(name string, value float64, labels Labels) { + keys, values := labelValues(labels) + var constants prometheus.Labels + if c.component != "" { + constants = prometheus.Labels{"component": c.component} + } + kind := prometheus.GaugeValue + if strings.HasSuffix(name, "_total") { + kind = prometheus.CounterValue + } + ch <- prometheus.MustNewConstMetric(prometheus.NewDesc("livepeer_"+name, metricHelp(name), keys, constants), kind, value, values...) + }) +} + +// Snapshot registers read-only collection. Callbacks must bound database reads +// and must not make network requests or mutate business state. +func (m *Metrics) Snapshot(collect func(Emit)) { + m.Registry.MustRegister(snapshotCollector{collect, m.Component}) +} +func (m *Metrics) Legacy(collect func(Emit)) { m.Registry.MustRegister(snapshotCollector{collect, ""}) } + +func Bool(value bool) float64 { + if value { + return 1 + } + return 0 +} +func ETH(value *big.Rat) float64 { + if value == nil { + return 0 + } + x, _ := new(big.Rat).Quo(value, new(big.Rat).SetInt(big.NewInt(1e18))).Float64() + return x +} + +// ErrorKind deliberately discards remote and transport error text. +func ErrorKind(err error) string { + if err == nil { + return "success" + } + if errors.Is(err, context.Canceled) { + return "cancelled" + } + if errors.Is(err, context.DeadlineExceeded) { + return "timeout" + } + if errors.Is(err, syscall.ECONNREFUSED) { + return "connection_refused" + } + var syntax *json.SyntaxError + if errors.As(err, &syntax) { + return "invalid_json" + } + var field *json.UnmarshalTypeError + if errors.As(err, &field) { + return "invalid_json_type" + } + var timeout net.Error + if errors.As(err, &timeout) && timeout.Timeout() { + return "timeout" + } + return "error" +} + +func (m *Metrics) RPC(method string, elapsed time.Duration, err error) { + labels := Labels{"method": method} + m.Add("rpc_requests_total", 1, labels.With("outcome", ErrorKind(err))) + m.Observe("rpc_request_duration_seconds", elapsed.Seconds(), labels) +} + +func (m *Metrics) Discovery(source int, elapsed time.Duration, err error) { + labels := Labels{"source_index": strconv.Itoa(source)} + m.Add("discovery_refreshes_total", 1, labels.With("outcome", ErrorKind(err))) + m.Observe("discovery_refresh_duration_seconds", elapsed.Seconds(), labels) +} + +type requestKey struct{} +type Request struct { + metrics *Metrics + Operation string + Identity Identity + App bool + Protocol string + Outcome string + status int + started, headers time.Time + transfers atomic.Pointer[transferCounters] + readFailed, writeFailed atomic.Bool + upstreamFailed atomic.Bool +} + +type transferCounters struct{ in, out prometheus.Counter } + +func (r *Request) trackTransfers(input, output string) { + labels := r.Identity.Labels() + r.transfers.Store(&transferCounters{ + in: r.metrics.counter("stream_transfer_bytes_total", labels.With("protocol", input).With("direction", "in")), + out: r.metrics.counter("stream_transfer_bytes_total", labels.With("protocol", output).With("direction", "out")), + }) +} + +func (r *Request) transferred(n int, incoming bool) { + if counters := r.transfers.Load(); counters != nil && n > 0 { + counter := counters.out + if incoming { + counter = counters.in + } + counter.Add(float64(n)) + } +} + +// closeWriter is forwarded only when the wrapped transport supports half-close. +// ReverseProxy relies on it to drain the other direction after an upgrade. +type closeWriter interface{ CloseWrite() error } +type halfCloseBody struct { + io.ReadWriteCloser + closeWriter +} +type halfCloseConnection struct { + net.Conn + closeWriter +} + +type upgradedBody struct { + upstreamBody + writer io.Writer +} + +type upstreamBody struct { + io.ReadCloser + state *Request +} + +func (b upstreamBody) Read(p []byte) (int, error) { + n, err := b.ReadCloser.Read(p) + if err != nil && !errors.Is(err, io.EOF) && !errors.Is(err, net.ErrClosed) { + b.state.upstreamFailed.Store(true) + } + return n, err +} + +func (b upgradedBody) Write(p []byte) (int, error) { + n, err := b.writer.Write(p) + if err != nil && !errors.Is(err, net.ErrClosed) { + b.state.upstreamFailed.Store(true) + } + return n, err +} + +// TrackResponse preserves upgraded bodies and observes failures after headers. +func TrackResponse(r *http.Request, response *http.Response) { + if response == nil { + return + } + if s := State(r); s != nil { + if body, ok := response.Body.(io.ReadWriteCloser); ok && response.StatusCode == http.StatusSwitchingProtocols { + response.Body = upgradedBody{upstreamBody{body, s}, body} + if half, ok := body.(closeWriter); ok { + response.Body = halfCloseBody{response.Body.(io.ReadWriteCloser), half} + } + } else { + response.Body = upstreamBody{response.Body, s} + } + } +} + +func State(r *http.Request) *Request { + state, _ := r.Context().Value(requestKey{}).(*Request) + return state +} +func Operation(r *http.Request, operation string) { + if s := State(r); s != nil && operation != "" { + s.Operation = operation + } +} +func Outcome(r *http.Request, outcome string) { + if s := State(r); s != nil { + s.Outcome = outcome + } +} + +func App(r *http.Request, identity Identity) { + s := State(r) + if s == nil || s.App || identity.Runner == "" { + return + } + s.App, s.Identity = true, identity + s.metrics.Gauge("app_calls_in_flight", identity.Labels()).Inc() + s.trackTransfers("http", s.Protocol) + if !s.headers.IsZero() { + s.metrics.Observe("app_response_header_duration_seconds", s.headers.Sub(s.started).Seconds(), identity.Labels().With("protocol", s.Protocol)) + } +} + +func Stream(r *http.Request, identity Identity, protocol string) { + if s := State(r); s != nil && !s.App && identity.Runner != "" { + s.Identity, s.Protocol = identity, protocol + s.trackTransfers(protocol, protocol) + } +} + +type reader struct { + io.ReadCloser + state *Request +} + +func (r reader) Read(p []byte) (int, error) { + n, err := r.ReadCloser.Read(p) + r.state.transferred(n, true) + if err != nil && !errors.Is(err, io.EOF) { + r.state.readFailed.Store(true) + } + return n, err +} + +type connection struct { + net.Conn + state *Request +} + +func (c connection) Read(p []byte) (int, error) { + n, err := c.Conn.Read(p) + c.state.transferred(n, true) + if err != nil && !errors.Is(err, io.EOF) && !errors.Is(err, net.ErrClosed) { + c.state.readFailed.Store(true) + } + return n, err +} +func (c connection) Write(p []byte) (int, error) { + n, err := c.Conn.Write(p) + c.state.transferred(n, false) + if err != nil && !errors.Is(err, net.ErrClosed) { + c.state.writeFailed.Store(true) + } + return n, err +} + +func httpMethod(method string) string { + switch method { + case "GET", "HEAD", "POST", "PUT", "PATCH", "DELETE", "OPTIONS", "CONNECT", "TRACE": + return method + } + return "other" +} + +// HTTP observes the entire handler lifetime, including upgraded connections. +// httpsnoop preserves the exact optional ResponseWriter interfaces. +func (m *Metrics) HTTP(w http.ResponseWriter, r *http.Request, serve http.HandlerFunc) { + s := &Request{metrics: m, Operation: "unknown", Protocol: "http", started: time.Now()} + r = r.WithContext(context.WithValue(r.Context(), requestKey{}, s)) + if r.Body != nil { + r.Body = reader{r.Body, s} + } + m.Gauge("http_requests_in_flight", nil).Inc() + mark := func(code int) { + if s.status == 0 && (code >= 200 || code == 101) { + s.status, s.headers = code, time.Now() + if code == http.StatusSwitchingProtocols { + s.Protocol = "websocket" + } else if s.Protocol == "http" && strings.HasPrefix(w.Header().Get("Content-Type"), "text/event-stream") { + s.Protocol = "sse" + } + if s.Identity.Runner != "" { + input := "http" + if s.Protocol == "trickle" || s.Protocol == "websocket" { + input = s.Protocol + } + s.trackTransfers(input, s.Protocol) + } + if s.App { + m.Observe("app_response_header_duration_seconds", s.headers.Sub(s.started).Seconds(), s.Identity.Labels().With("protocol", s.Protocol)) + } + } + } + write := func(next func([]byte) (int, error), p []byte) (int, error) { + n, err := next(p) + s.transferred(n, false) + if err != nil { + s.writeFailed.Store(true) + } + return n, err + } + wrapped := httpsnoop.Wrap(w, httpsnoop.Hooks{ + WriteHeader: func(next httpsnoop.WriteHeaderFunc) httpsnoop.WriteHeaderFunc { + return func(code int) { mark(code); next(code) } + }, + Write: func(next httpsnoop.WriteFunc) httpsnoop.WriteFunc { + return func(p []byte) (int, error) { + mark(200) + return write(next, p) + } + }, + ReadFrom: func(_ httpsnoop.ReadFromFunc) httpsnoop.ReadFromFunc { + return func(src io.Reader) (int64, error) { + mark(200) + // Count completed writes during the copy, not the final aggregate. + n, err := io.Copy(writeFunc(func(p []byte) (int, error) { return write(w.Write, p) }), src) + if err != nil && !s.writeFailed.Load() { + s.upstreamFailed.Store(true) + } + return n, err + } + }, + Flush: func(next httpsnoop.FlushFunc) httpsnoop.FlushFunc { return func() { mark(200); next() } }, + FlushError: func(next httpsnoop.FlushErrorFunc) httpsnoop.FlushErrorFunc { + return func() error { + mark(200) + err := next() + if err != nil { + s.writeFailed.Store(true) + } + return err + } + }, + Hijack: func(next httpsnoop.HijackFunc) httpsnoop.HijackFunc { + return func() (net.Conn, *bufio.ReadWriter, error) { + conn, rw, err := next() + if err != nil { + s.writeFailed.Store(true) + return conn, rw, err + } + mark(101) + var observed net.Conn = connection{conn, s} + if half, ok := conn.(closeWriter); ok { + observed = halfCloseConnection{observed, half} + } + return observed, rw, nil + } + }, + }) + defer func() { + panicked := recover() + if panicked != nil && s.Outcome == "" { + s.Outcome = "stream_error" + } + m.Gauge("http_requests_in_flight", nil).Dec() + elapsed := time.Since(s.started).Seconds() + if s.status == 0 && r.Context().Err() == nil && panicked == nil { + mark(200) + } + labels := Labels{"operation": s.Operation, "method": httpMethod(r.Method)} + m.Add("http_requests_total", 1, labels.With("status", strconv.Itoa(s.status))) + m.Observe("http_request_duration_seconds", elapsed, labels) + if s.Outcome != "session_stopped" && (r.Context().Err() != nil || (s.Outcome == "" && (s.readFailed.Load() || s.writeFailed.Load()) && !s.upstreamFailed.Load())) { + s.Outcome = "client_cancelled" + } + if s.Outcome == "" { + switch { + case s.upstreamFailed.Load(): + s.Outcome = "stream_error" + case s.status >= 500: + s.Outcome = "error" + case s.status == 402: + s.Outcome = "payment_required" + case s.status == 480: + s.Outcome = "refresh_required" + case s.status == 482: + s.Outcome = "no_payment_needed" + case s.status >= 400: + s.Outcome = "rejected" + default: + s.Outcome = "success" + } + } + if s.App { + identity := s.Identity.Labels() + m.Gauge("app_calls_in_flight", identity).Dec() + appLabels := identity.With("protocol", s.Protocol) + m.Add("app_calls_total", 1, appLabels.With("outcome", s.Outcome)) + m.Observe("app_call_duration_seconds", elapsed, appLabels) + } + if s.Identity.Runner != "" { + labels := s.Identity.Labels().With("protocol", s.Protocol) + if s.Outcome == "stream_error" || s.Outcome == "transport_error" { + m.Add("stream_errors_total", 1, labels.With("outcome", s.Outcome)) + } + } + if panicked != nil { + panic(panicked) + } + }() + serve(wrapped, r) +} + +// writeFunc deliberately has no ReaderFrom, so copies report each write. +type writeFunc func([]byte) (int, error) + +func (f writeFunc) Write(p []byte) (int, error) { return f(p) } diff --git a/internal/observability/metrics_test.go b/internal/observability/metrics_test.go new file mode 100644 index 0000000..423949b --- /dev/null +++ b/internal/observability/metrics_test.go @@ -0,0 +1,161 @@ +package observability_test + +import ( + "context" + "fmt" + "io" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" + "github.com/stretchr/testify/require" +) + +// ResponseRecorder commits informational responses; a real server permits a +// later final response. Preserve that behavior in this controlled writer. +type provisionalRecorder struct{ *httptest.ResponseRecorder } + +func (w provisionalRecorder) WriteHeader(status int) { + if status >= 200 { + w.ResponseRecorder.WriteHeader(status) + } +} + +func TestHTTPStreamingAndFailures(t *testing.T) { + for _, outcome := range []string{"success", "stream_error", "client_cancelled", "session_stopped"} { + t.Run(outcome, func(t *testing.T) { + m := observability.New("test") + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + r := httptest.NewRequest("POST", "/private-path?token=private", strings.NewReader("upload")).WithContext(ctx) + serve := func(w http.ResponseWriter, r *http.Request) { + observability.Operation(r, "application") + observability.App(r, observability.Identity{App: "registered", Runner: "runner", Mode: "persistent"}) + _, err := io.Copy(io.Discard, r.Body) + require.NoError(t, err) + require.EqualValues(t, 6, test.MetricSum(t, m.Registry, "stream_transfer_bytes_total", map[string]string{"direction": "in"})) + _, hijack := w.(http.Hijacker) + require.False(t, hijack, "must preserve the underlying interface set") + w.WriteHeader(103) + require.Zero(t, test.MetricSum(t, m.Registry, "app_response_header_duration_seconds", nil)) + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(200) + require.EqualValues(t, 1, test.MetricSum(t, m.Registry, "app_response_header_duration_seconds", nil)) + require.NoError(t, http.NewResponseController(w).Flush()) + _, err = w.Write([]byte("data: hello\n\n")) + require.NoError(t, err) + require.EqualValues(t, 13, test.MetricSum(t, m.Registry, "stream_transfer_bytes_total", map[string]string{"direction": "out", "protocol": "sse"})) + require.Zero(t, test.MetricSum(t, m.Registry, "app_calls_total", nil), "completion is recorded only after the stream ends") + switch outcome { + case "stream_error": + panic(http.ErrAbortHandler) + case "client_cancelled": + cancel() + case "session_stopped": + observability.Outcome(r, "session_stopped") + } + } + if outcome == "stream_error" { + require.Panics(t, func() { m.HTTP(provisionalRecorder{httptest.NewRecorder()}, r, serve) }) + } else { + m.HTTP(provisionalRecorder{httptest.NewRecorder()}, r, serve) + } + require.EqualValues(t, 1, test.MetricSum(t, m.Registry, "app_calls_total", map[string]string{"outcome": outcome, "protocol": "sse"})) + require.EqualValues(t, 1, test.MetricSum(t, m.Registry, "app_response_header_duration_seconds", nil)) + require.Zero(t, test.MetricSum(t, m.Registry, "http_requests_in_flight", nil)) + require.Zero(t, test.MetricSum(t, m.Registry, "app_calls_in_flight", nil)) + require.EqualValues(t, len("data: hello\n\n"), test.MetricSum(t, m.Registry, "stream_transfer_bytes_total", map[string]string{"direction": "out"})) + }) + } +} + +type failedResponseWriter struct{ *httptest.ResponseRecorder } + +func (w failedResponseWriter) Write([]byte) (int, error) { return 0, io.ErrClosedPipe } + +func TestFailedResponsePreservesOutcome(t *testing.T) { + for _, outcome := range []string{"transport_error", "capacity", "rejected", "session_stopped"} { + for _, cancelled := range []bool{false, true} { + t.Run(fmt.Sprintf("%s/cancelled=%t", outcome, cancelled), func(t *testing.T) { + m := observability.New("test") + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + if cancelled { + cancel() + } + m.HTTP(failedResponseWriter{httptest.NewRecorder()}, httptest.NewRequest("GET", "/", nil).WithContext(ctx), func(w http.ResponseWriter, r *http.Request) { + observability.App(r, observability.Identity{App: "model", Runner: "runner"}) + observability.Outcome(r, outcome) + w.WriteHeader(502) + _, _ = w.Write([]byte("failure")) + }) + want := outcome + if cancelled && outcome != "session_stopped" { + want = "client_cancelled" + } + require.EqualValues(t, 1, test.MetricSum(t, m.Registry, "app_calls_total", map[string]string{"outcome": want})) + }) + } + } +} + +type readFromRecorder struct{ provisionalRecorder } + +func (w readFromRecorder) ReadFrom(r io.Reader) (int64, error) { return io.Copy(w.ResponseRecorder, r) } + +type readFunc func([]byte) (int, error) + +func (f readFunc) Read(p []byte) (int, error) { return f(p) } + +func TestStreamingReadFromProgress(t *testing.T) { + m := observability.New("test") + m.HTTP(readFromRecorder{provisionalRecorder{httptest.NewRecorder()}}, httptest.NewRequest("GET", "/events", nil), func(w http.ResponseWriter, r *http.Request) { + observability.App(r, observability.Identity{App: "model", Runner: "runner", Mode: "persistent"}) + w.Header().Set("Content-Type", "text/event-stream") + reads := 0 + _, err := io.Copy(w, readFunc(func(p []byte) (int, error) { + reads++ + if reads == 1 { + return copy(p, "data: hello\n\n"), nil + } + require.EqualValues(t, 13, test.MetricSum(t, m.Registry, "stream_transfer_bytes_total", map[string]string{"direction": "out"})) + require.EqualValues(t, 1, test.MetricSum(t, m.Registry, "app_response_header_duration_seconds", nil)) + require.Zero(t, test.MetricSum(t, m.Registry, "app_calls_total", nil)) + return 0, io.EOF + })) + require.NoError(t, err) + }) + require.EqualValues(t, 1, test.MetricSum(t, m.Registry, "app_calls_total", nil)) + require.EqualValues(t, 13, test.MetricSum(t, m.Registry, "stream_transfer_bytes_total", map[string]string{"direction": "out"})) +} + +func TestUnknownInputsDoNotCreateSeries(t *testing.T) { + m := observability.New("test") + for i := range 50 { + m.HTTP(httptest.NewRecorder(), httptest.NewRequest(fmt.Sprintf("PRIVATE-%d", i), fmt.Sprintf("/private/%d?secret=private", i), nil), func(w http.ResponseWriter, r *http.Request) { + observability.App(r, observability.Identity{}) + observability.Stream(r, observability.Identity{}, "trickle") + w.Header().Set("Content-Type", "text/event-stream") + w.WriteHeader(404) + _, _ = w.Write([]byte("unowned")) + }) + } + require.Empty(t, test.MetricSamples(t, m.Registry, "stream_transfer_bytes_total", nil)) + require.Empty(t, test.MetricSamples(t, m.Registry, "app_calls_total", nil)) + families, err := m.Registry.Gather() + require.NoError(t, err) + for _, family := range families { + for _, sample := range family.Metric { + for _, label := range sample.Label { + require.NotContains(t, label.GetValue(), "private") + require.NotContains(t, label.GetValue(), "PRIVATE") + } + } + } + require.EqualValues(t, 50, test.MetricSum(t, m.Registry, "http_requests_total", map[string]string{"operation": "unknown", "method": "other"})) + other := observability.New("test") + require.Zero(t, test.MetricSum(t, other.Registry, "http_requests_total", nil), "registries must be isolated") +} diff --git a/internal/test/metrics.go b/internal/test/metrics.go new file mode 100644 index 0000000..eb88790 --- /dev/null +++ b/internal/test/metrics.go @@ -0,0 +1,56 @@ +package test + +import ( + "testing" + + "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" + "github.com/stretchr/testify/require" +) + +// MetricSum sums samples matching a label subset. Histograms return their +// observation count, allowing behavioral tests to verify exactly-once recording. +func MetricSum(t *testing.T, registry prometheus.Gatherer, name string, labels map[string]string) float64 { + t.Helper() + var sum float64 + for _, metric := range MetricSamples(t, registry, name, labels) { + if metric.Counter != nil { + sum += metric.Counter.GetValue() + } else if metric.Gauge != nil { + sum += metric.Gauge.GetValue() + } else if metric.Histogram != nil { + sum += float64(metric.Histogram.GetSampleCount()) + } + } + return sum +} + +// MetricSamples distinguishes absent series from samples whose value is zero. +func MetricSamples(t *testing.T, registry prometheus.Gatherer, name string, labels map[string]string) []*dto.Metric { + t.Helper() + families, err := registry.Gather() + require.NoError(t, err) + var samples []*dto.Metric + for _, family := range families { + if family.GetName() != "livepeer_"+name { + continue + } + for _, metric := range family.Metric { + matched := true + for key, value := range labels { + found := false + for _, label := range metric.Label { + if label.GetName() == key && label.GetValue() == value { + found = true + } + } + matched = matched && found + } + if !matched { + continue + } + samples = append(samples, metric) + } + } + return samples +} diff --git a/orchestrator/app.go b/orchestrator/app.go index 66767b2..c066b7c 100644 --- a/orchestrator/app.go +++ b/orchestrator/app.go @@ -24,6 +24,7 @@ import ( "github.com/livepeer/node/cmd/version" "github.com/livepeer/node/destination" "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/nodeconfig" "github.com/livepeer/node/nodeconfig/migrations" "github.com/livepeer/node/pm" @@ -272,6 +273,7 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { return fmt.Errorf("configure payment RPC (LIVEPEER_ORCHESTRATOR_RPC_URL or --rpc-url-file): %w", err) } defer rpc.Close() + rpc.SetObserver(registry.metrics.RPC) paymentChainID = new(big.Int).SetUint64(*p.ChainID) if err := rpc.CheckChainID(parent, paymentChainID); err != nil { return fmt.Errorf("verify payment RPC chain ID (check LIVEPEER_ORCHESTRATOR_RPC_URL or --rpc-url-file, --chain-id and --network): %w", err) @@ -292,9 +294,11 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { if p.ETHUSDFeed != nil { rate, until, err := contracts.WeiPerUSD(parent, *p.ETHUSDFeed, p.PriceMaxAge) if err != nil { + registry.metrics.Add("price_feed_updates_total", 1, observability.Labels{"outcome": "error"}) return fmt.Errorf("read ETH/USD price feed (check --eth-usd-feed, --price-max-age, and LIVEPEER_ORCHESTRATOR_RPC_URL or --rpc-url-file): %w", err) } registry.setRate(rate, until) + registry.metrics.Add("price_feed_updates_total", 1, observability.Labels{"outcome": "success"}) } recipient := redeemerKey.Address() if p.OrchestratorAddress != nil { @@ -306,13 +310,22 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { } } registry.proxyTemplate = p.ProxyURLTemplate + logger := slog.New(slog.NewTextHandler(logOut, nil)) + registry.logger = logger.With("component", "orchestrator") if err := loadStatic(p.RunnerConfig, registry); err != nil { return fmt.Errorf("load static runners from %q (--runner-config or LIVEPEER_ORCHESTRATOR_RUNNER_CONFIG): %w", p.RunnerConfig, err) } - logger := slog.New(slog.NewTextHandler(logOut, nil)) app := NewServer(registry, runnerPolicy, proxyPolicy, logger) + logger = app.logger defer app.Close() app.SetPayment(engine) + readiness := &paidReadiness{interval: p.HeartbeatInterval} + if engine != nil { + registry.metrics.Gauge("redemption_last_success_timestamp_seconds", nil).Set(0) + registry.metrics.Gauge("redemption_worker_last_completed_timestamp_seconds", nil).Set(0) + readiness.account = redeemerKey.Address() + redeemerDB.readiness = readiness + } mainListener, err := net.Listen("tcp", p.Listen.String()) if err != nil { return fmt.Errorf("cannot start orchestrator HTTP listener on %s; choose an available address with --listen or LIVEPEER_ORCHESTRATOR_LISTEN: %w", p.Listen, err) @@ -329,14 +342,14 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { _, _ = io.WriteString(w, "ok\n") }) metricsMux.HandleFunc("GET /readyz", func(w http.ResponseWriter, _ *http.Request) { + if engine != nil && !readiness.ready(registry) { + http.Error(w, "orchestrator payment dependencies unavailable", http.StatusServiceUnavailable) + return + } w.WriteHeader(http.StatusOK) _, _ = io.WriteString(w, "ready\n") }) - metricsMux.HandleFunc("GET /metrics", func(w http.ResponseWriter, _ *http.Request) { - runners, sessions := registry.Counts() - w.Header().Set("Content-Type", "text/plain; version=0.0.4") - _, _ = fmt.Fprintf(w, "livepeer_runners %d\nlivepeer_sessions %d\n", runners, sessions) - }) + metricsMux.Handle("GET /metrics", registry.metrics.Handler()) ctx, cancel := signal.NotifyContext(parent, syscall.SIGINT, syscall.SIGTERM) defer cancel() if engine != nil { @@ -350,7 +363,7 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { var workers sync.WaitGroup workers.Go(func() { errs <- mainServer.Serve(mainListener) }) workers.Go(func() { errs <- metricsServer.Serve(metricsListener) }) - logger.Info("orchestrator started", "listen", p.Listen, "metrics_listen", p.MetricsListen) + logger.Info("orchestrator started", "event", "started", "operation", "serve", "outcome", "success", "listen", p.Listen, "metrics_listen", p.MetricsListen) // Independent bounded workers keep slow RPC/health calls off the billing // and expiry paths. Every worker uses the shutdown context and is joined. startWorker := func(period, timeout time.Duration, work func(context.Context)) { @@ -372,25 +385,39 @@ func Serve(parent context.Context, p Params, logOut io.Writer) (result error) { startWorker(p.HeartbeatInterval, time.Second, func(context.Context) { registry.Expire() }) workers.Go(func() { app.runO2RKeepalives(ctx, 10*time.Second) }) if engine != nil { + startWorker(p.HeartbeatInterval, 30*time.Second, func(ctx context.Context) { + readiness.check(ctx, redeemerDB, paymentChain, engine, registry.metrics, logger) + }) if p.ETHUSDFeed != nil { startWorker(time.Hour, 30*time.Second, func(ctx context.Context) { rate, until, err := paymentChain.Contracts.WeiPerUSD(ctx, *p.ETHUSDFeed, p.PriceMaxAge) if err != nil { - logger.Error("price feed unavailable", "error", err) + registry.metrics.Add("price_feed_updates_total", 1, observability.Labels{"outcome": "error"}) + logger.Error("price feed unavailable", "event", "price_feed", "operation", "refresh", "outcome", "error", "error_kind", observability.ErrorKind(err)) return } registry.setRate(rate, until) + registry.metrics.Add("price_feed_updates_total", 1, observability.Labels{"outcome": "success"}) }) } startWorker(time.Second, 5*time.Second, app.ChargePaidSessions) startWorker(time.Minute, 5*time.Second, func(ctx context.Context) { if err := engine.PruneControlState(ctx); err != nil { - logger.Error("payment retention", "error", err) + logger.Error("payment retention", "event", "payment_retention", "operation", "prune", "outcome", "error", "error_kind", observability.ErrorKind(err)) } }) startWorker(p.HeartbeatInterval, 30*time.Second, func(ctx context.Context) { - for _, err := range ProcessRedemptions(ctx, redeemerDB, paymentChain, redeemerKey, paymentChainID) { - logger.Error("redemption", "error", err) + failures := ProcessRedemptions(ctx, redeemerDB, paymentChain, redeemerKey, paymentChainID) + for _, err := range failures { + registry.metrics.Add("redemption_errors_total", 1, observability.Labels{"error_kind": observability.ErrorKind(err)}) + logger.Error("redemption failed", "event", "redemption_pass", "operation", "redeem", "outcome", "error", "error_kind", observability.ErrorKind(err)) + } + readiness.mu.Lock() + readiness.workerCompleted = time.Now() + readiness.mu.Unlock() + registry.metrics.Gauge("redemption_worker_last_completed_timestamp_seconds", nil).Set(float64(time.Now().Unix())) + if len(failures) == 0 { + registry.metrics.Gauge("redemption_last_success_timestamp_seconds", nil).Set(float64(time.Now().Unix())) } }) } diff --git a/orchestrator/app_test.go b/orchestrator/app_test.go index 4d41aec..2dc826e 100644 --- a/orchestrator/app_test.go +++ b/orchestrator/app_test.go @@ -17,17 +17,20 @@ import ( "path/filepath" "strconv" "strings" + "sync" "sync/atomic" "testing" "time" "github.com/BurntSushi/toml" ethcommon "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/crypto" "github.com/holiman/uint256" "github.com/j0sh/boa/pkg/boa" "github.com/livepeer/node/eth" "github.com/livepeer/node/internal/test" "github.com/livepeer/node/nodeconfig" + "github.com/livepeer/node/pm" "github.com/livepeer/node/pm/wire" "github.com/stretchr/testify/require" ) @@ -56,6 +59,7 @@ func TestPaidHTTPStartup(t *testing.T) { mainPort, metricsPort := freeTCPPort(t), freeTCPPort(t) address := fmt.Sprintf("http://127.0.0.1:%d", mainPort) p := paymentKeystoreParams(t, "http://127.0.0.1:1") + p.HeartbeatInterval = time.Second p.KeystoreFile, p.KeystorePasswordFile = test.WriteFixedKeystore(t) key, err := eth.OpenKeystoreFile(p.KeystoreFile, p.KeystorePasswordFile) require.NoError(t, err) @@ -65,27 +69,48 @@ func TestPaidHTTPStartup(t *testing.T) { p.OrchestratorAddress = &recipient } var requests atomic.Int32 + dependencies := make(chan struct{}) + releaseDependencies := sync.OnceFunc(func() { close(dependencies) }) rpc := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - requests.Add(1) var req struct { Method string ID json.RawMessage + Params []json.RawMessage } require.NoError(t, json.NewDecoder(r.Body).Decode(&req)) + if req.Method != "eth_chainId" { + select { + case <-dependencies: + case <-r.Context().Done(): + return + } + } + requests.Add(1) var result any = "0x1" switch req.Method { - case "eth_chainId": + case "eth_chainId", "eth_getBalance", "eth_gasPrice", "eth_maxPriorityFeePerGas": + case "eth_getTransactionCount": + result = "0x0" + case "eth_estimateGas": + _ = json.NewEncoder(w).Encode(map[string]any{"jsonrpc": "2.0", "id": req.ID, "error": map[string]any{"code": -32000, "message": "ticket estimation unavailable"}}) + return case "eth_getBlockByNumber": result = map[string]string{"number": "0x32", "hash": ethcommon.HexToHash("0xabcd").Hex()} case "eth_call": // Reuse the 32-byte encoding of 1 for calls returning an address, round, hash, or bool. result = fmt.Sprintf("0x%064x", 1) + var call struct{ Input string } + require.NoError(t, json.Unmarshal(req.Params[0], &call)) + if strings.HasPrefix(call.Input, fmt.Sprintf("0x%x", crypto.Keccak256([]byte("usedTickets(bytes32)"))[:4])) { + result = fmt.Sprintf("0x%064x", 0) + } default: t.Errorf("unexpected RPC %s", req.Method) } require.NoError(t, json.NewEncoder(w).Encode(map[string]any{"jsonrpc": "2.0", "id": req.ID, "result": result})) })) defer rpc.Close() + defer releaseDependencies() p.RPCURL = mustURL(t, rpc.URL) p.Listen = netip.MustParseAddrPort(fmt.Sprintf("0.0.0.0:%d", mainPort)) p.MetricsListen = netip.MustParseAddrPort(fmt.Sprintf("127.0.0.1:%d", metricsPort)) @@ -118,7 +143,16 @@ func TestPaidHTTPStartup(t *testing.T) { response, err := http.Get("http://" + p.MetricsListen.String() + "/readyz") require.NoError(t, err) response.Body.Close() - require.Equal(t, http.StatusOK, response.StatusCode) + require.Equal(t, http.StatusServiceUnavailable, response.StatusCode) + // Seed before releasing either worker's chain observation. The other + // wallet case keeps its empty queue, exercising both first-pass paths. + if separate { + store, err := OpenRedeemerDB(p.RedeemerDB) + require.NoError(t, err) + defer store.Close() + require.NoError(t, store.StoreWinningTicket(&pm.SignedTicket{Ticket: &pm.Ticket{PayerAddress: recipient, Recipient: recipient, FaceValue: big.NewInt(1000), WinProb: big.NewInt(100), TicketNonce: 1, RecipientRandHash: crypto.Keccak256Hash([]byte("failed ticket")), CreationRound: 1, ParamsExpirationBlock: big.NewInt(0)}, Sig: make([]byte, 65), RecipientRand: big.NewInt(1)})) + } + releaseDependencies() response, err = http.Get(address + "/external/discovery") require.NoError(t, err) defer response.Body.Close() @@ -142,6 +176,21 @@ func TestPaidHTTPStartup(t *testing.T) { require.NoError(t, err) require.Equal(t, recipient.Bytes(), info.Address) require.Equal(t, recipient.Bytes(), info.TicketParams.Recipient) + require.Eventually(t, func() bool { + ready, err := http.Get("http://" + p.MetricsListen.String() + "/readyz") + if err != nil { + return false + } + defer ready.Body.Close() + return ready.StatusCode == http.StatusOK + }, 7*time.Second, 20*time.Millisecond, "paid readiness must become healthy after the first dependency and worker observations") + response, err = http.Get("http://" + p.MetricsListen.String() + "/metrics") + require.NoError(t, err) + metrics, err := io.ReadAll(response.Body) + response.Body.Close() + require.NoError(t, err) + require.Equal(t, separate, strings.Contains(string(metrics), "livepeer_redemption_errors_total{"), "readiness must include completion of the first worker pass, including ticket failure") + }) } } diff --git a/orchestrator/http.go b/orchestrator/http.go index 0e18ada..562e166 100644 --- a/orchestrator/http.go +++ b/orchestrator/http.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "io" + "log" "log/slog" "maps" "net/http" @@ -17,6 +18,7 @@ import ( "github.com/livepeer/node/destination" discovery "github.com/livepeer/node/discovery/shared" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/trickle" ) @@ -43,6 +45,8 @@ type Server struct { } func NewServer(registry *Registry, runnerPolicy, proxyPolicy destination.Policy, logger *slog.Logger) *Server { + logger = logger.With("component", "orchestrator") + registry.logger = logger s := &Server{registry: registry, logger: logger, mux: http.NewServeMux(), channels: map[string]*channel{}, o2r: map[string]string{}} serviceURL, _ := url.Parse(registry.service) s.basePath = strings.TrimRight(serviceURL.Path, "/") @@ -76,10 +80,17 @@ func NewServer(registry *Registry, runnerPolicy, proxyPolicy destination.Policy, s.trickleServer = trickle.ConfigureServer(trickle.TrickleServerConfig{ BasePath: "/ai/trickle/", Mux: s.mux, BeforeDelete: s.beforeDeleteChannel, }) + registry.mu.Lock() + registry.server = s + registry.mu.Unlock() return s } func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { + s.registry.metrics.HTTP(w, r, s.serveHTTP) +} + +func (s *Server) serveHTTP(w http.ResponseWriter, r *http.Request) { if strings.Contains(r.URL.Path+"/", "/../") { fail(w, http.StatusBadRequest, "invalid path") return @@ -103,6 +114,43 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { } } stream := proxyID != "" || strings.HasPrefix(r.URL.Path, "/ai/trickle/") || strings.HasPrefix(r.URL.Path, "/proxy/") || strings.HasPrefix(r.URL.Path, "/run/") || strings.HasSuffix(r.URL.Path, "/app") || strings.Contains(r.URL.Path, "/app/") + _, pattern := s.mux.Handler(r) + observability.Operation(r, pattern) + if proxyID != "" { + observability.Operation(r, "generated_proxy") + } + // Resolve only known routes before admission so rejected application work is + // attributed without turning attacker-supplied runner IDs into label values. + parts := strings.Split(strings.Trim(r.URL.Path, "/"), "/") + if pattern != "" && len(parts) >= 3 && parts[0] == "apps" { + if parts[2] == "app" { + observability.App(r, s.registry.identity(parts[1], "")) + } else if len(parts) >= 5 && parts[2] == "session" && parts[4] == "app" { + observability.App(r, s.registry.identity(parts[1], parts[3])) + } + } + generated := proxyID + if generated == "" && pattern != "" && len(parts) >= 2 && (parts[0] == "proxy" || parts[0] == "run") { + generated = parts[1] + } + if generated != "" { + if s.registry.singleShotProxy(generated) { + observability.App(r, s.registry.identity(generated, "")) + } else if _, id, sid, _, ok := s.registry.proxyTarget(generated); ok { + observability.App(r, s.registry.identity(id, sid)) + } + } + if strings.HasPrefix(r.URL.Path, "/ai/trickle/") { + parts := strings.Split(strings.TrimPrefix(r.URL.Path, "/ai/trickle/"), "/") + s.mu.Lock() + ch := s.channels[parts[0]] + var identity observability.Identity + if ch != nil { + identity = ch.identity + } + s.mu.Unlock() + observability.Stream(r, identity, "trickle") + } slots := s.controlSlots if stream { slots = s.streamSlots @@ -113,6 +161,8 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { case slots <- struct{}{}: defer func() { <-slots }() default: + s.registry.metrics.Add("http_admission_rejections_total", 1, observability.Labels{"pool": map[bool]string{true: "stream", false: "control"}[stream]}) + observability.Outcome(r, "capacity") fail(w, http.StatusServiceUnavailable, "server busy") return } @@ -125,7 +175,17 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { s.mux.ServeHTTP(w, r) } -func (s *Server) SetPayment(engine *PaymentEngine) { s.payment = engine } +func (s *Server) SetPayment(engine *PaymentEngine) { + s.payment = engine + if engine != nil { + engine.metrics, engine.identity = s.registry.metrics, s.registry.identity + engine.store.logger = s.logger + if engine.store.metrics == nil { + engine.store.metrics = s.registry.metrics + engine.store.metrics.Snapshot(engine.store.collectMetrics) + } + } +} func (s *Server) Close() { s.registry.Close() @@ -147,6 +207,13 @@ func fail(w http.ResponseWriter, status int, message string) { writeJSON(w, status, map[string]string{"error": message}) } +func failReservation(w http.ResponseWriter, r *http.Request, status int, err error) { + if capacityError(err) { + observability.Outcome(r, "capacity") + } + fail(w, status, err.Error()) +} + func decode(r *http.Request, value any) error { decoder := json.NewDecoder(http.MaxBytesReader(nil, r.Body, maxControlBody)) if err := decoder.Decode(value); err != nil { @@ -190,7 +257,7 @@ func (s *Server) heartbeat(w http.ResponseWriter, r *http.Request) { return } s.mu.Lock() - s.newChannel(id, "o2r", "application/json", resp.RunnerID, "") + s.newChannel(id, "o2r", "application/json", resp.RunnerID, "").identity = runnerIdentity(resp.RunnerID, current) s.o2r[resp.RunnerID] = id s.mu.Unlock() s.registry.mu.Unlock() @@ -248,7 +315,7 @@ func (s *Server) unregister(w http.ResponseWriter, r *http.Request) { func (s *Server) discovery(w http.ResponseWriter, r *http.Request) { if n, _ := writeJSON(w, http.StatusOK, s.registry.Discovery()); n > discovery.MaxBody { - s.logger.WarnContext(r.Context(), "orchestrator discovery response exceeds signer size limit", "response_bytes", n, "max_bytes", discovery.MaxBody) + s.logger.WarnContext(r.Context(), "orchestrator discovery response exceeds signer size limit", "event", "discovery_response", "operation", "discovery", "outcome", "error", "error_kind", "response_limit", "response_bytes", n, "max_bytes", discovery.MaxBody) } } @@ -258,7 +325,7 @@ func (s *Server) reserve(w http.ResponseWriter, r *http.Request) { } id, appURL, controlURL, status, err := s.registry.Reserve(r.PathValue("runner_id")) if err != nil { - fail(w, status, err.Error()) + failReservation(w, r, status, err) return } writeJSON(w, http.StatusOK, map[string]string{"session_id": id, "app_url": appURL, "control_url": controlURL}) @@ -322,6 +389,7 @@ func (s *Server) createProxy(w http.ResponseWriter, r *http.Request) { } func (s *Server) proxySession(w http.ResponseWriter, r *http.Request) { + observability.App(r, s.registry.identity(r.PathValue("runner_id"), r.PathValue("session_id"))) target, token, status, err := s.registry.sessionTarget(r.PathValue("runner_id"), r.PathValue("session_id")) if err != nil { fail(w, status, err.Error()) @@ -332,6 +400,7 @@ func (s *Server) proxySession(w http.ResponseWriter, r *http.Request) { } func (s *Server) proxySingleShot(w http.ResponseWriter, r *http.Request) { + observability.App(r, s.registry.identity(r.PathValue("runner_id"), "")) if s.proxyPaidSingleShot(w, r) { return } @@ -343,10 +412,10 @@ func (s *Server) proxySingleShot(w http.ResponseWriter, r *http.Request) { } id, _, _, status, err := s.registry.ReserveWithID(runnerID, id) if err != nil { - fail(w, status, err.Error()) + failReservation(w, r, status, err) return } - defer s.registry.ReleaseBySession(id) + defer s.registry.ReleaseBySession(id, "completed") target, token, status, err := s.registry.sessionTarget(runnerID, id) if err != nil { fail(w, status, err.Error()) @@ -367,6 +436,7 @@ func (s *Server) proxyGenerated(w http.ResponseWriter, r *http.Request) { fail(w, http.StatusNotFound, "proxy not found") return } + observability.App(r, s.registry.identity(runnerID, sid)) control := s.registry.runnerServiceURL() + "/runner/" + url.PathEscape(runnerID) + "/session/" + url.PathEscape(sid) transport := s.proxyTransport if target.runner { @@ -376,6 +446,11 @@ func (s *Server) proxyGenerated(w http.ResponseWriter, r *http.Request) { } func (s *Server) proxy(w http.ResponseWriter, r *http.Request, transport http.RoundTripper, target *url.URL, appPath, runnerID, sid, token, control string) { + kind := "runner" + if transport == s.proxyTransport { + kind = "session_proxy" + } + transport = upstreamObserver{transport, s.registry.metrics, s.registry.identity(runnerID, sid), kind} sessionCtx, ok := s.registry.sessionContext(runnerID, sid) if !ok || sessionCtx.Err() != nil { fail(w, http.StatusNotFound, "session not found") @@ -397,11 +472,20 @@ func (s *Server) proxy(w http.ResponseWriter, r *http.Request, transport http.Ro }) defer stop() defer cancel() + defer func() { + if errors.Is(context.Cause(sessionCtx), errRunnerUnavailable) { + observability.Outcome(r, "transport_error") + } else if sessionCtx.Err() != nil { + observability.Outcome(r, "session_stopped") + } + }() proxy := &httputil.ReverseProxy{ + ErrorLog: log.New(proxyLog{s.logger.With("runner_id", runnerID, "session_id", sid)}, "", 0), Transport: transport, FlushInterval: -1, ErrorHandler: func(w http.ResponseWriter, _ *http.Request, err error) { - s.logger.Warn("runner proxy failed", "runner_id", runnerID, "session_id", sid, "error_kind", "upstream_failure") + observability.Outcome(r, "transport_error") + s.logger.Warn("runner proxy failed", "event", "proxy_failed", "operation", "proxy", "outcome", "error", "runner_id", runnerID, "session_id", sid, "error_kind", "upstream_failure") fail(w, http.StatusBadGateway, "runner destination unavailable") }, Rewrite: func(req *httputil.ProxyRequest) { @@ -427,6 +511,14 @@ func (s *Server) proxy(w http.ResponseWriter, r *http.Request, transport http.Ro proxy.ServeHTTP(w, r.WithContext(ctx)) } +// ReverseProxy's internal messages may include transport-provided error text. +type proxyLog struct{ logger *slog.Logger } + +func (l proxyLog) Write(p []byte) (int, error) { + l.logger.Warn("proxy stream interrupted", "event", "proxy_stream", "operation", "proxy", "outcome", "error", "error_kind", "stream_error") + return len(p), nil +} + func (s *Server) createChannels(w http.ResponseWriter, r *http.Request) { if !s.callbackAuthorized(r) { fail(w, http.StatusUnauthorized, "invalid session token") @@ -447,6 +539,7 @@ func (s *Server) createChannels(w http.ResponseWriter, r *http.Request) { fail(w, http.StatusNotFound, "session not found") return } + identity := s.registry.identity(r.PathValue("runner_id"), r.PathValue("session_id")) for _, item := range body.Channels { if item.Name == "" { fail(w, http.StatusBadRequest, "channel name required") @@ -494,7 +587,7 @@ func (s *Server) createChannels(w http.ResponseWriter, r *http.Request) { if item.MimeType == "" { item.MimeType = "application/octet-stream" } - s.newChannel(id, item.Name, item.MimeType, r.PathValue("runner_id"), r.PathValue("session_id")) + s.newChannel(id, item.Name, item.MimeType, r.PathValue("runner_id"), r.PathValue("session_id")).identity = identity existing[item.Name] = id } ch := s.channels[id] diff --git a/orchestrator/http_test.go b/orchestrator/http_test.go index 01d7fef..b399205 100644 --- a/orchestrator/http_test.go +++ b/orchestrator/http_test.go @@ -15,6 +15,7 @@ import ( "github.com/gorilla/websocket" "github.com/livepeer/node/destination" + "github.com/livepeer/node/internal/test" "github.com/stretchr/testify/require" ) @@ -210,6 +211,11 @@ func TestSessionProxyStreamsSSEAndWebSocket(t *testing.T) { require.NoError(t, err) require.Equal(t, websocket.TextMessage, kind) require.Equal(t, "echo", string(message)) + require.NoError(t, conn.Close()) + require.Eventually(t, func() bool { return test.MetricSum(t, registry.metrics.Registry, "app_calls_total", nil) == 2 }, time.Second, 10*time.Millisecond) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"protocol": "websocket"})) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"protocol": "sse", "outcome": "client_cancelled"})) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "app_calls_in_flight", nil)) } func TestRunnerDestinationDeniedWithoutGrant(t *testing.T) { @@ -284,6 +290,14 @@ func TestGeneratedProxyHasSeparateDestinationGrant(t *testing.T) { record = httptest.NewRecorder() srv.ServeHTTP(record, httptest.NewRequest(http.MethodGet, "/proxy/"+created.ProxyID, nil)) require.Equal(t, http.StatusOK, record.Code) + create = httptest.NewRequest("POST", "/runner/"+registered.RunnerID+"/session/"+sid+"/channels", strings.NewReader(`{"channels":[{"name":"events"}]}`)) + create.Header.Set("Livepeer-Session-Token", token) + record = httptest.NewRecorder() + srv.ServeHTTP(record, create) + require.Equal(t, 200, record.Code) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "trickle_channels", map[string]string{"kind": "session"}), "the replacement server owns the only snapshot") + _, err = registry.metrics.Registry.Gather() + require.NoError(t, err) } func TestRunnerExpires(t *testing.T) { @@ -291,10 +305,15 @@ func TestRunnerExpires(t *testing.T) { registered, _, err := registry.Heartbeat(heartbeatRequest{RunnerURL: "https://runner.example", App: "test", Mode: "persistent", Capacity: 1}, "bootstrap") require.NoError(t, err) require.NotEmpty(t, registered.RunnerID) + require.Len(t, test.MetricSamples(t, registry.metrics.Registry, "runner_sessions", map[string]string{"runner_id": registered.RunnerID, "state": "active"}), 1) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "runner_sessions", nil)) time.Sleep(3 * time.Millisecond) registry.Expire() count, _ := registry.Counts() require.Zero(t, count) + for _, name := range []string{"runner_registered", "runner_sessions", "runner_capacity_available"} { + require.Empty(t, test.MetricSamples(t, registry.metrics.Registry, name, nil)) + } } func TestTrickleChannelsScopedToSession(t *testing.T) { diff --git a/orchestrator/lifecycle_test.go b/orchestrator/lifecycle_test.go index daac836..5b94aad 100644 --- a/orchestrator/lifecycle_test.go +++ b/orchestrator/lifecycle_test.go @@ -15,6 +15,8 @@ import ( "github.com/gorilla/websocket" "github.com/livepeer/node/destination" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" "github.com/stretchr/testify/require" ) @@ -54,7 +56,10 @@ func TestRunnerStopDrainsProxy(t *testing.T) { }) w := httptest.NewRecorder() go func() { - server.proxy(w, httptest.NewRequest(http.MethodPost, appURL, nil), transport, target, "", "r", sid, token, "") + registry.metrics.HTTP(w, httptest.NewRequest(http.MethodPost, appURL, nil), func(w http.ResponseWriter, r *http.Request) { + observability.App(r, registry.identity("r", sid)) + server.proxy(w, r, transport, target, "", "r", sid, token, "") + }) done <- time.Now() }() <-started @@ -75,6 +80,7 @@ func TestRunnerStopDrainsProxy(t *testing.T) { } require.Equal(t, scenario.delay, (<-done).Sub(released)) require.Equal(t, scenario.status, w.Code) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"outcome": "session_stopped"})) }) }) } @@ -83,7 +89,7 @@ func TestRunnerStopDrainsProxy(t *testing.T) { func TestReleaseCancelsActiveProxy(t *testing.T) { for _, mode := range []string{"persistent", "single-shot"} { for _, protocol := range []string{"http", "sse", "websocket"} { - for _, issuer := range []string{"client", "shutdown"} { + for _, issuer := range []string{"client", "shutdown", "expired", "health", "unregistered"} { t.Run(mode+"/"+protocol+"/"+issuer, func(t *testing.T) { started := make(chan http.Header, 1) ended := make(chan struct{}) @@ -112,7 +118,14 @@ func TestReleaseCancelsActiveProxy(t *testing.T) { policy, err := destination.New("runner", []string{strings.TrimPrefix(upstream.URL, "http://")}) require.NoError(t, err) registry := NewRegistry("bootstrap", "http://orchestrator.example", time.Second, time.Minute) - require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", RunnerURL: upstream.URL, App: "test", Mode: mode, Capacity: 1})) + var credential string + if issuer == "expired" || issuer == "unregistered" { + registered, _, err := registry.Heartbeat(heartbeatRequest{RunnerID: "runner", RunnerURL: upstream.URL, App: "test", Mode: mode, Capacity: 1}, "bootstrap") + require.NoError(t, err) + credential = registered.HeartbeatSecret + } else { + require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", RunnerURL: upstream.URL, App: "test", Mode: mode, Capacity: 1})) + } app := NewServer(registry, policy, policy, slog.New(slog.NewTextHandler(io.Discard, nil))) server := httptest.NewServer(app) defer server.Close() @@ -123,7 +136,7 @@ func TestReleaseCancelsActiveProxy(t *testing.T) { require.NoError(t, err) path = "/apps/runner/session/" + sid + "/app" } - clientDone := make(chan struct{}) + clientDone, headersReady := make(chan struct{}), make(chan struct{}) if protocol == "websocket" { conn, _, err := websocket.DefaultDialer.Dial("ws"+strings.TrimPrefix(server.URL, "http")+path, nil) require.NoError(t, err) @@ -134,6 +147,7 @@ func TestReleaseCancelsActiveProxy(t *testing.T) { defer close(clientDone) response, err := http.Get(server.URL + path) if err == nil { + close(headersReady) defer response.Body.Close() _, _ = io.Copy(io.Discard, response.Body) } @@ -148,9 +162,40 @@ func TestReleaseCancelsActiveProxy(t *testing.T) { sid := headers.Get("Livepeer-Session-Id") require.NotEmpty(t, sid) require.NotEmpty(t, headers.Get("Livepeer-Session-Token")) - if issuer == "shutdown" { + if protocol == "sse" { + select { + case <-headersReady: + case <-time.After(3 * time.Second): + t.Fatal("SSE headers did not arrive") + } + } + reason, outcome := "client_stop", "session_stopped" + switch issuer { + case "shutdown": app.Close() - } else { + reason = "shutdown" + case "expired": + registry.mu.Lock() + registry.runners["runner"].Last = time.Now().Add(-2 * time.Minute) + registry.mu.Unlock() + registry.Expire() + reason, outcome = "runner_expired", "transport_error" + case "health": + registry.mu.Lock() + registry.runners["runner"].HealthURL = upstream.URL + "/healthz" + registry.mu.Unlock() + health := &http.Client{Transport: roundTripFunc(func(*http.Request) (*http.Response, error) { + return &http.Response{StatusCode: 503, Body: http.NoBody}, nil + })} + for range 3 { + registry.CheckStaticHealth(t.Context(), health) + } + reason, outcome = "runner_unhealthy", "transport_error" + case "unregistered": + _, err := registry.Unregister("runner", credential) + require.NoError(t, err) + reason = "runner_unregistered" + default: response, err := http.Post(server.URL+"/apps/runner/session/"+sid+"/stop", "", nil) require.NoError(t, err) require.Equal(t, http.StatusOK, response.StatusCode) @@ -169,6 +214,15 @@ func TestReleaseCancelsActiveProxy(t *testing.T) { } _, sessions := registry.Counts() require.Zero(t, sessions) + require.Eventually(t, func() bool { return test.MetricSum(t, registry.metrics.Registry, "app_calls_total", nil) == 1 }, time.Second, time.Millisecond) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"outcome": outcome})) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "session_ends_total", map[string]string{"reason": reason})) + wantErrors := 0 + if outcome == "transport_error" { + wantErrors = 1 + } + require.EqualValues(t, wantErrors, test.MetricSum(t, registry.metrics.Registry, "stream_errors_total", nil)) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "app_calls_in_flight", nil)) }) } } diff --git a/orchestrator/metrics.go b/orchestrator/metrics.go new file mode 100644 index 0000000..8dda380 --- /dev/null +++ b/orchestrator/metrics.go @@ -0,0 +1,255 @@ +package orchestrator + +import ( + "context" + "errors" + "log/slog" + "math/big" + "net/http" + "sync" + "time" + + "github.com/ethereum/go-ethereum/common" + "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/pm" +) + +func runnerIdentity(id string, item *runner) observability.Identity { + return observability.Identity{App: item.App, Runner: id, Mode: item.Mode} +} + +func (r *Registry) identity(id, sid string) observability.Identity { + r.mu.Lock() + defer r.mu.Unlock() + if item := r.runners[id]; item != nil { + if sess := item.Sessions[sid]; sess != nil { + return sess.identity + } + return runnerIdentity(id, item) + } + return observability.Identity{} +} + +func (r *Registry) runnerEvent(id string, item *runner, event string) { + r.metrics.Add("runner_events_total", 1, runnerIdentity(id, item).Labels().With("event", event)) + if r.logger != nil { + r.logger.Info("runner state changed", "event", "runner_"+event, "operation", "runner_lifecycle", "runner_id", id, "app", item.App, "outcome", "success") + } +} + +func (r *Registry) collectMetrics(emit observability.Emit) { + r.mu.Lock() + defer r.mu.Unlock() + for id, item := range r.runners { + labels := runnerIdentity(id, item).Labels() + ready := r.usable(item) && r.priceAvailable(item) + emit("runner_registered", 1, labels) + emit("runner_ready", observability.Bool(ready), labels) + emit("runner_capacity", float64(item.Capacity), labels) + available := 0 + if ready { + available = max(item.Capacity-len(item.Sessions), 0) + } + emit("runner_capacity_available", float64(available), labels) + if !item.Static { + emit("runner_last_heartbeat_timestamp_seconds", float64(item.Last.Unix()), labels) + } + type group struct { + identity observability.Identity + pending bool + } + counts := map[group]int{{runnerIdentity(id, item), false}: 0, {runnerIdentity(id, item), true}: 0} + for _, sess := range item.Sessions { + counts[group{sess.identity, sess.pending}]++ + } + for key, count := range counts { + state := "active" + if key.pending { + state = "pending" + } + emit("runner_sessions", float64(count), key.identity.Labels().With("state", state)) + } + } + if r.server != nil { + r.server.collectMetrics(emit) + } +} + +func (s *Server) collectMetrics(emit observability.Emit) { + s.mu.Lock() + control, session := 0, 0 + for _, ch := range s.channels { + if ch.sessionID == "" { + control++ + } else { + session++ + } + } + s.mu.Unlock() + emit("trickle_channels", float64(control), observability.Labels{"kind": "control"}) + emit("trickle_channels", float64(session), observability.Labels{"kind": "session"}) + emit("trickle_buffered_bytes", float64(s.trickleServer.BufferedBytes()), nil) +} + +type upstreamObserver struct { + http.RoundTripper + metrics *observability.Metrics + identity observability.Identity + kind string +} + +func (t upstreamObserver) RoundTrip(r *http.Request) (*http.Response, error) { + start := time.Now() + response, err := t.RoundTripper.RoundTrip(r) + observability.TrackResponse(r, response) + labels := t.identity.Labels().With("destination", t.kind) + outcome := observability.ErrorKind(err) + if err == nil && response.StatusCode >= 500 { + outcome = "http_5xx" + } else if err == nil && response.StatusCode >= 400 { + outcome = "http_4xx" + } + t.metrics.Add("upstream_requests_total", 1, labels.With("outcome", outcome)) + t.metrics.Observe("upstream_response_header_duration_seconds", time.Since(start).Seconds(), labels) + return response, err +} + +// paidReadiness tracks worker completion separately from per-ticket progress. +// A failed ticket cannot make a live worker appear dead. +type paidReadiness struct { + mu sync.Mutex + completed time.Time + workerCompleted time.Time + account common.Address + chain, active, storage bool + snapshot eth.ChainSnapshot + interval time.Duration +} + +func (p *paidReadiness) ready(registry *Registry) bool { + p.mu.Lock() + limit := max(time.Minute, 3*p.interval) + ok := p.chain && p.active && p.storage && !p.completed.IsZero() && time.Since(p.completed) <= limit && !p.workerCompleted.IsZero() && time.Since(p.workerCompleted) <= limit + p.mu.Unlock() + registry.mu.Lock() + fresh := registry.rateUntil.IsZero() || time.Now().Before(registry.rateUntil) + registry.mu.Unlock() + return ok && fresh +} + +func (p *paidReadiness) check(ctx context.Context, store *RedeemerDB, chain eth.PaymentChain, engine *PaymentEngine, metrics *observability.Metrics, logger *slog.Logger) { + snapshot, chainErr := chain.Snapshot(ctx) + active := false + if chainErr == nil { + active, chainErr = chain.IsActiveAt(ctx, engine.recipient, snapshot) + } + dbCtx, cancel := context.WithTimeout(ctx, time.Second) + storageErr := store.checkStorage(dbCtx) + cancel() + p.mu.Lock() + changed := p.completed.IsZero() || p.chain != (chainErr == nil) || p.active != active || p.storage != (storageErr == nil) + p.completed, p.chain, p.active, p.storage = time.Now(), chainErr == nil, active, storageErr == nil + if chainErr == nil { + p.snapshot = snapshot + } + p.mu.Unlock() + metrics.Gauge("dependency_healthy", observability.Labels{"dependency": "chain"}).Set(observability.Bool(chainErr == nil && active)) + metrics.Gauge("dependency_healthy", observability.Labels{"dependency": "payment_storage"}).Set(observability.Bool(storageErr == nil)) + if chainErr == nil { + if snapshot.Block != nil { + metrics.Gauge("chain_snapshot_block", nil).Set(float64(snapshot.Block.Int64())) + } + if snapshot.Round != nil { + metrics.Gauge("chain_snapshot_round", nil).Set(float64(snapshot.Round.Int64())) + } + metrics.Gauge("chain_snapshot_last_success_timestamp_seconds", nil).Set(float64(time.Now().Unix())) + } + if balance, err := chain.Contracts.RPC.BalanceAt(ctx, p.account, nil); err == nil { + metrics.Gauge("redeemer_gas_balance_eth", nil).Set(observability.ETH(new(big.Rat).SetInt(balance))) + } + if changed { + logger.Info("payment dependency state changed", "event", "payment_dependencies", "operation", "check", "outcome", map[bool]string{true: "success", false: "unavailable"}[chainErr == nil && active && storageErr == nil]) + } +} + +// A rolled-back empty write validates the payment table and SQLite's ability to +// enter a write transaction, without changing payment or redemption state. +func (s *RedeemerDB) checkStorage(ctx context.Context) error { + tx, err := s.db.BeginTx(ctx, nil) + if err != nil { + return err + } + defer tx.Rollback() + if _, err := tx.ExecContext(ctx, `UPDATE winning_tickets SET enqueued_at=enqueued_at WHERE 0`); err != nil { + return err + } + return tx.Rollback() +} + +// paymentObservation preserves the public error while identifying its cause. +type paymentObservation struct { + error + outcome string +} + +func (e paymentObservation) Unwrap() error { return e.error } + +func paymentOutcome(err error) string { + switch { + case errors.Is(err, context.Canceled), errors.Is(err, context.DeadlineExceeded): + return observability.ErrorKind(err) + } + if observed, ok := errors.AsType[paymentObservation](err); ok { + return observed.outcome + } + switch { + case errors.Is(err, errPaymentSessionCapacity), errors.Is(err, errPaymentTicketCapacity): + return "capacity" + case errors.Is(err, ErrFixedAlreadyCharged): + return "already_charged" + case errors.Is(err, ErrInsufficientBalance): + return "insufficient_balance" + case errors.Is(err, ErrInvalidPayment), errors.Is(err, pm.ErrPayerUnavailable): + return "rejected" + case errors.Is(err, ErrMissingChallenge): + return "missing_challenge" + default: + return observability.ErrorKind(err) + } +} + +func paymentAppOutcome(err error) string { + switch outcome := paymentOutcome(err); outcome { + case "rejected", "missing_challenge", "insufficient_balance", "already_charged": + return "rejected" + case "cancelled": + return "client_cancelled" + case "capacity": + return "capacity" + default: + return "error" + } +} + +func (e *PaymentEngine) paymentLabels(runner, manifest string) observability.Labels { + if runner == "" { + e.mu.Lock() + if session := e.sessions[manifest]; session != nil { + runner = session.runner + } + e.mu.Unlock() + } + if e.identity == nil { + return nil + } + return e.identity(runner, manifest).Labels() +} + +func (e *PaymentEngine) recordPayment(operation string, err error, labels observability.Labels) { + outcome := paymentOutcome(err) + e.metrics.Add("payment_operations_total", 1, labels.With("operation", operation).With("outcome", outcome)) + if e.store != nil && e.store.logger != nil && operation != "charge" { + e.store.logger.Info("payment observed", "event", "payment", "operation", operation, "outcome", outcome, "app", labels["app"], "runner_id", labels["runner_id"]) + } +} diff --git a/orchestrator/metrics_test.go b/orchestrator/metrics_test.go new file mode 100644 index 0000000..bf71073 --- /dev/null +++ b/orchestrator/metrics_test.go @@ -0,0 +1,322 @@ +package orchestrator + +import ( + "bufio" + "bytes" + "encoding/base64" + "encoding/json" + "io" + "log/slog" + "math/big" + "net" + "net/http" + "net/http/httptest" + "net/url" + "path/filepath" + "testing" + "time" + + "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" + "github.com/livepeer/node/pm/wire" + "github.com/stretchr/testify/require" +) + +func TestRunnerCapacityOutcomes(t *testing.T) { + for _, paid := range []bool{false, true} { + name := "unpaid" + if paid { + name = "paid" + } + t.Run(name, func(t *testing.T) { + registry, app := reviewServer(t, "http://127.0.0.1:1") + defer app.Close() + registry.proxyTemplate = "https://{proxy}.apps.example" + if paid { + registry.SetWeiPerUSD(big.NewRat(1, 1)) + } + require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", App: "model", Mode: "single-shot", RunnerURL: "http://127.0.0.1:1", Capacity: 1, Proxy: true, PriceInfo: priceInfo{Price: "1", Currency: "usd", Unit: "fixed"}})) + _, _, _, _, err := registry.ReserveWithID("runner", "held") + require.NoError(t, err) + if paid { + store, err := OpenRedeemerDB(filepath.Join(t.TempDir(), "payments.sqlite")) + require.NoError(t, err) + defer store.Close() + key := paymentTestKey(t) + engine, err := NewPaymentEngine(store, paymentTestChain{}, key.Address(), big.NewInt(11), big.NewInt(1)) + require.NoError(t, err) + app.SetPayment(engine) + _, err = engine.MakeChallenge(t.Context(), "runner", "new", key.Address(), 1, "fixed", registry.service) + require.NoError(t, err) + } + for _, route := range []string{"/apps/runner/app", "/run/runner", "/proxy/runner", "https://runner.apps.example/"} { + request := httptest.NewRequest("GET", route, nil) + if paid { + request.Header.Set("Livepeer-Payment", "pending") + request.Header.Set("Livepeer-Segment", base64.StdEncoding.EncodeToString(wire.EncodeSegData(wire.SegData{ManifestID: []byte("new"), Auth: wire.AuthToken{SessionID: "new"}}))) + } + response := httptest.NewRecorder() + app.ServeHTTP(response, request) + require.Equal(t, 503, response.Code, response.Body.String()) + } + require.EqualValues(t, 4, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"outcome": "capacity"})) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"outcome": "error"})) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "upstream_requests_total", nil)) + }) + } +} + +func TestUpgradePreservesHalfClose(t *testing.T) { + for _, clientFirst := range []bool{true, false} { + name := "backend_first" + if clientFirst { + name = "client_first" + } + t.Run(name, func(t *testing.T) { + backendReply := make(chan string, 1) + upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + conn, rw, err := w.(http.Hijacker).Hijack() + require.NoError(t, err) + defer conn.Close() + require.NoError(t, conn.SetDeadline(time.Now().Add(3*time.Second))) + _, err = io.WriteString(rw, "HTTP/1.1 101 Switching Protocols\r\nConnection: Upgrade\r\nUpgrade: custom\r\n\r\n") + require.NoError(t, err) + require.NoError(t, rw.Flush()) + if clientFirst { + body, err := io.ReadAll(rw) + require.NoError(t, err) + _, err = io.WriteString(conn, "reply:"+string(body)) + require.NoError(t, err) + } else { + _, err = io.WriteString(conn, "payload") + require.NoError(t, err) + require.NoError(t, conn.(interface{ CloseWrite() error }).CloseWrite()) + body, err := io.ReadAll(rw) + require.NoError(t, err) + backendReply <- string(body) + } + })) + defer upstream.Close() + registry, app := reviewServer(t, upstream.URL) + defer app.Close() + require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", App: "model", Mode: "single-shot", RunnerURL: upstream.URL, Capacity: 1})) + server := httptest.NewServer(app) + defer server.Close() + u, err := url.Parse(server.URL) + require.NoError(t, err) + address, err := net.ResolveTCPAddr("tcp", u.Host) + require.NoError(t, err) + conn, err := net.DialTCP("tcp", nil, address) + require.NoError(t, err) + defer conn.Close() + require.NoError(t, conn.SetDeadline(time.Now().Add(4*time.Second))) + _, err = io.WriteString(conn, "GET /apps/runner/app HTTP/1.1\r\nHost: "+u.Host+"\r\nConnection: Upgrade\r\nUpgrade: custom\r\n\r\n") + require.NoError(t, err) + reader := bufio.NewReader(conn) + response, err := http.ReadResponse(reader, &http.Request{Method: "GET"}) + require.NoError(t, err) + require.Equal(t, 101, response.StatusCode) + if clientFirst { + _, err = io.WriteString(conn, "payload") + require.NoError(t, err) + require.NoError(t, conn.CloseWrite()) + body, err := io.ReadAll(reader) + require.NoError(t, err) + require.Equal(t, "reply:payload", string(body)) + } else { + body, err := io.ReadAll(reader) + require.NoError(t, err) + require.Equal(t, "payload", string(body)) + _, err = io.WriteString(conn, "reply:"+string(body)) + require.NoError(t, err) + require.NoError(t, conn.CloseWrite()) + select { + case reply := <-backendReply: + require.Equal(t, "reply:payload", reply) + case <-time.After(4 * time.Second): + t.Fatal("backend did not receive the client reply after half-close") + } + } + }) + } +} + +func TestApplicationMetricsAndInventory(t *testing.T) { + upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(503) })) + defer upstream.Close() + registry, app := reviewServer(t, upstream.URL) + defer app.Close() + require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", App: "model", Mode: "single-shot", RunnerURL: upstream.URL, Capacity: 1, Proxy: true})) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "runner_registered", map[string]string{"app": "model"})) + for _, state := range []string{"pending", "active"} { + samples := test.MetricSamples(t, registry.metrics.Registry, "runner_sessions", map[string]string{"runner_id": "runner", "state": state}) + require.Len(t, samples, 1) + require.Zero(t, samples[0].Gauge.GetValue()) + } + for _, path := range []string{"/apps/runner/app", "/run/runner", "/proxy/runner"} { + response := httptest.NewRecorder() + app.ServeHTTP(response, httptest.NewRequest("POST", path, nil)) + require.Equal(t, 503, response.Code) + } + require.EqualValues(t, 3, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"app": "model", "outcome": "error"})) + require.EqualValues(t, 3, test.MetricSum(t, registry.metrics.Registry, "upstream_requests_total", map[string]string{"outcome": "http_5xx"})) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "runner_sessions", nil)) + // Admission rejection is still an application call, but never an upstream attempt. + for range cap(app.streamSlots) { + app.streamSlots <- struct{}{} + } + app.ServeHTTP(httptest.NewRecorder(), httptest.NewRequest("POST", "/run/runner", nil)) + for range cap(app.streamSlots) { + <-app.streamSlots + } + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"outcome": "capacity"})) + require.EqualValues(t, 3, test.MetricSum(t, registry.metrics.Registry, "upstream_requests_total", nil)) + // An application change affects new sessions, never an existing identity. + registry.mu.Lock() + registry.runners["runner"].Mode = "persistent" + registry.mu.Unlock() + sid, _, _, _, err := registry.Reserve("runner") + require.NoError(t, err) + registry.mu.Lock() + registry.runners["runner"].App = "new-model" + registry.mu.Unlock() + require.Equal(t, "model", registry.identity("runner", sid).App) + registry.ReleaseBySession(sid) + require.EqualValues(t, 4, test.MetricSum(t, registry.metrics.Registry, "session_ends_total", map[string]string{"app": "model"})) +} + +func TestPaidDependencyObservationsRecover(t *testing.T) { + f, store, ticket, chain, key := newRecoveryTest(t, 15) + metrics := observability.New("orchestrator") + registry := NewRegistry("", "http://localhost", time.Second, time.Minute) + p := &paidReadiness{interval: time.Second, workerCompleted: time.Now(), account: key.Address()} + var events bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&events, nil)).With("component", "orchestrator") + check := func() { + p.check(t.Context(), store, chain, &PaymentEngine{recipient: ticket.Recipient}, metrics, logger) + } + f.mu.Lock() + f.snapshotError = true + f.mu.Unlock() + _, err := store.db.Exec("PRAGMA query_only=ON") + require.NoError(t, err) + check() + var event map[string]any + require.NoError(t, json.Unmarshal(events.Bytes(), &event)) + for key, value := range map[string]string{"component": "orchestrator", "event": "payment_dependencies", "operation": "check", "outcome": "unavailable"} { + require.Equal(t, value, event[key]) + } + first := events.String() + check() + require.Equal(t, first, events.String(), "unchanged dependencies do not repeat the event") + f.mu.Lock() + f.snapshotError = false + f.mu.Unlock() + _, err = store.db.Exec("PRAGMA query_only=OFF") + require.NoError(t, err) + check() + require.True(t, p.ready(registry)) + var enqueued string + require.NoError(t, store.db.QueryRow("SELECT enqueued_at FROM winning_tickets WHERE sig=?", ticket.Sig).Scan(&enqueued)) + _, err = store.db.Exec("PRAGMA query_only=ON") + require.NoError(t, err) + check() + require.False(t, p.storage) + require.False(t, p.ready(registry)) + require.Zero(t, test.MetricSum(t, metrics.Registry, "dependency_healthy", map[string]string{"dependency": "payment_storage"})) + _, err = store.db.Exec("PRAGMA query_only=OFF") + require.NoError(t, err) + check() + require.True(t, p.storage) + require.True(t, p.ready(registry)) + var after string + require.NoError(t, store.db.QueryRow("SELECT enqueued_at FROM winning_tickets WHERE sig=?", ticket.Sig).Scan(&after)) + require.Equal(t, enqueued, after, "health observations must not change accounting state") + for _, failure := range []string{"snapshot", "active", "worker", "observation", "price"} { + t.Run(failure, func(t *testing.T) { + f.mu.Lock() + f.snapshotError, f.activeError = failure == "snapshot", failure == "active" + f.mu.Unlock() + if failure == "worker" { + p.workerCompleted = time.Now().Add(-time.Hour) + } + check() + if failure == "observation" { + p.completed = time.Now().Add(-time.Hour) + } + if failure == "price" { + registry.rateUntil = time.Now().Add(-time.Second) + } + require.False(t, p.ready(registry)) + f.mu.Lock() + f.snapshotError, f.activeError = false, false + f.mu.Unlock() + p.workerCompleted, registry.rateUntil = time.Now(), time.Time{} + check() + require.True(t, p.ready(registry)) + }) + } +} + +func TestUpstreamFailureAfterHeaders(t *testing.T) { + upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Content-Length", "100") + _, _ = w.Write([]byte("short response")) + })) + defer upstream.Close() + registry, app := reviewServer(t, upstream.URL) + defer app.Close() + require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", App: "model", Mode: "single-shot", RunnerURL: upstream.URL, Capacity: 1})) + response := httptest.NewRecorder() + app.ServeHTTP(response, httptest.NewRequest("GET", "/apps/runner/app", nil)) + require.Equal(t, 200, response.Code, "the upstream status was already forwarded") + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "app_calls_total", map[string]string{"outcome": "stream_error"})) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "stream_errors_total", nil)) + require.Zero(t, test.MetricSum(t, registry.metrics.Registry, "app_calls_in_flight", nil)) +} + +func TestRedemptionMetricsDurableAndIdempotent(t *testing.T) { + _, store, ticket, _, _ := newRecoveryTest(t, 14) + store.metrics = observability.New("orchestrator") + store.metrics.Snapshot(store.collectMetrics) + store.readiness = &paidReadiness{completed: time.Now(), chain: true, interval: time.Second, snapshot: eth.ChainSnapshot{Block: new(big.Int).Sub(ticket.ParamsExpirationBlock, big.NewInt(1)), Round: big.NewInt(ticket.CreationRound)}} + require.EqualValues(t, 1, test.MetricSum(t, store.metrics.Registry, "redemption_queue_tickets", map[string]string{"state": "waiting"})) + var enqueued string + require.NoError(t, store.db.QueryRow("SELECT enqueued_at FROM winning_tickets WHERE sig=?", ticket.Sig).Scan(&enqueued)) + store.readiness.snapshot.Block = new(big.Int).Set(ticket.ParamsExpirationBlock) + require.EqualValues(t, 1, test.MetricSum(t, store.metrics.Registry, "redemption_queue_tickets", map[string]string{"state": "eligible"})) + _, err := store.db.Exec("UPDATE winning_tickets SET params_expiration_block='broken' WHERE sig=?", ticket.Sig) + require.NoError(t, err) + values := map[string]float64{} + store.collectMetrics(func(name string, value float64, _ observability.Labels) { values[name] = value }) + require.Equal(t, map[string]float64{"collector_healthy": 0}, values, "collection failure must expose health and omit unavailable statistics") + _, err = store.db.Exec("UPDATE winning_tickets SET params_expiration_block=? WHERE sig=?", ticket.ParamsExpirationBlock.String(), ticket.Sig) + require.NoError(t, err) + require.NoError(t, store.setTicketPhase(t.Context(), ticket.Sig, "awaiting_finality")) + require.NoError(t, store.setTicketPhase(t.Context(), ticket.Sig, "awaiting_finality")) + require.EqualValues(t, 1, test.MetricSum(t, store.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "awaiting_finality"})) + require.NoError(t, store.setTicketPhase(t.Context(), ticket.Sig, "retryable")) + require.NoError(t, store.setTicketPhase(t.Context(), ticket.Sig, "retryable")) + require.EqualValues(t, 1, test.MetricSum(t, store.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"})) + _, err = store.db.Exec(`CREATE TRIGGER fail_transition BEFORE UPDATE OF phase ON redemption_attempts WHEN NEW.phase='awaiting_finality' BEGIN SELECT RAISE(ABORT,'storage failure'); END`) + require.NoError(t, err) + require.Error(t, store.setTicketPhase(t.Context(), ticket.Sig, "awaiting_finality")) + require.EqualValues(t, 1, test.MetricSum(t, store.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "awaiting_finality"})) + _, err = store.db.Exec(`DROP TRIGGER fail_transition`) + require.NoError(t, err) + require.NoError(t, store.finishTicket(t.Context(), ticket.Sig, "used", "")) + require.NoError(t, store.finishTicket(t.Context(), ticket.Sig, "used", "")) + require.NoError(t, store.finishTicket(t.Context(), ticket.Sig, "confirmed", "")) + require.EqualValues(t, 1, test.MetricSum(t, store.metrics.Registry, "redemption_settlements_total", nil)) + require.Zero(t, test.MetricSum(t, store.metrics.Registry, "redemption_queue_tickets", nil)) + store = reopenRecoveryStore(t, store) + var restored string + require.NoError(t, store.db.QueryRow("SELECT enqueued_at FROM winning_tickets WHERE sig=?", ticket.Sig).Scan(&restored)) + require.Equal(t, enqueued, restored) + require.NoError(t, store.Close()) + store.metrics = observability.New("orchestrator") + store.metrics.Snapshot(store.collectMetrics) + require.Zero(t, test.MetricSum(t, store.metrics.Registry, "collector_healthy", nil)) + require.Zero(t, test.MetricSum(t, store.metrics.Registry, "redemption_queue_tickets", nil)) +} diff --git a/orchestrator/migrations/003_ticket_enqueue_time.sql b/orchestrator/migrations/003_ticket_enqueue_time.sql new file mode 100644 index 0000000..12eef3e --- /dev/null +++ b/orchestrator/migrations/003_ticket_enqueue_time.sql @@ -0,0 +1,5 @@ +-- UP +ALTER TABLE winning_tickets ADD COLUMN enqueued_at TEXT; +UPDATE winning_tickets SET enqueued_at=strftime('%Y-%m-%dT%H:%M:%fZ','now'); +-- DOWN +ALTER TABLE winning_tickets DROP COLUMN enqueued_at; diff --git a/orchestrator/payment.go b/orchestrator/payment.go index 39a2b4c..0068a44 100644 --- a/orchestrator/payment.go +++ b/orchestrator/payment.go @@ -11,6 +11,7 @@ import ( ethcommon "github.com/ethereum/go-ethereum/common" "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" ) func paymentPrice(price priceInfo) (int64, bool) { @@ -39,7 +40,8 @@ func (s *Server) challenge(w http.ResponseWriter, r *http.Request, runnerID stri wei, _ := paymentPrice(price) challenge, err := s.payment.MakeChallenge(r.Context(), runnerID, manifest, ethcommon.HexToAddress(payerRaw), wei, price.Unit, s.registry.service) if err != nil { - s.logger.Error("payment challenge failed", "runner_id", runnerID, "error", err) + observability.Outcome(r, paymentAppOutcome(err)) + s.logger.Warn("payment challenge failed", "event", "payment_challenge", "operation", "challenge", "runner_id", runnerID, "outcome", paymentOutcome(err), "error_kind", observability.ErrorKind(err)) fail(w, 502, "payment challenge unavailable") return } @@ -59,6 +61,7 @@ func (s *Server) paidReceipt(w http.ResponseWriter, r *http.Request, runnerID st return "", false } if _, _, err := s.payment.Receive(r.Context(), runnerID, manifest, r.Header.Get("Livepeer-Payment"), r.Header.Get("Livepeer-Segment")); err != nil { + observability.Outcome(r, paymentAppOutcome(err)) status := http.StatusBadRequest if errors.Is(err, ErrMissingChallenge) { status = http.StatusNotFound @@ -102,7 +105,7 @@ func (s *Server) reservePaid(w http.ResponseWriter, r *http.Request) bool { } id, appURL, controlURL, status, err := s.registry.reserveWithPrice(runnerID, manifest, &price) if err != nil { - fail(w, status, err.Error()) + failReservation(w, r, status, err) return true } if _, ok := s.paidReceipt(w, r, runnerID, price); !ok { @@ -110,6 +113,7 @@ func (s *Server) reservePaid(w http.ResponseWriter, r *http.Request) bool { return true } if err := s.payment.Charge(r.Context(), id, time.Now()); err != nil { + observability.Outcome(r, paymentAppOutcome(err)) s.registry.ReleaseBySession(id) fail(w, 402, "insufficient payment balance") return true @@ -152,14 +156,15 @@ func (s *Server) proxyPaidSingleShot(w http.ResponseWriter, r *http.Request) boo } id, _, _, status, err := s.registry.reserveWithPrice(runnerID, manifest, &price) if err != nil { - fail(w, status, err.Error()) + failReservation(w, r, status, err) return true } - defer s.registry.ReleaseBySession(id) + defer s.registry.ReleaseBySession(id, "completed") if _, ok := s.paidReceipt(w, r, runnerID, price); !ok { return true } if err := s.payment.Charge(r.Context(), id, time.Now()); err != nil { + observability.Outcome(r, paymentAppOutcome(err)) fail(w, 402, "insufficient payment balance") return true } @@ -230,8 +235,12 @@ func (s *Server) ChargePaidSessions(ctx context.Context) { } for _, id := range s.registry.PaidSessions() { if err := s.payment.Charge(ctx, id, time.Now()); err != nil && !errors.Is(err, ErrFixedAlreadyCharged) { - s.logger.Warn("paid session ended", "session_id", id, "error", err) - s.registry.ReleaseBySession(id) + s.logger.Warn("paid session ended", "event", "payment_billing", "operation", "charge", "session_id", id, "outcome", paymentOutcome(err), "error_kind", observability.ErrorKind(err)) + reason := "billing_error" + if errors.Is(err, ErrInsufficientBalance) { + reason = "insufficient_balance" + } + s.registry.ReleaseBySession(id, reason) } } } diff --git a/orchestrator/payment_engine.go b/orchestrator/payment_engine.go index 847409d..e60d6d7 100644 --- a/orchestrator/payment_engine.go +++ b/orchestrator/payment_engine.go @@ -13,6 +13,7 @@ import ( ethcommon "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm" "github.com/livepeer/node/pm/wire" ) @@ -22,6 +23,8 @@ var maxWinProb = new(big.Int).Sub(new(big.Int).Lsh(big.NewInt(1), 256), big.NewI // PaymentEngine owns process-local payment challenges and session accounting. // Winning tickets and redemption state are durable in the orchestrator redeemer. type PaymentEngine struct { + metrics *observability.Metrics + identity func(string, string) observability.Identity mu sync.Mutex store *RedeemerDB chain pm.PaymentChain @@ -71,7 +74,13 @@ type Challenge struct { // MakeChallenge returns a Python/Go runner compatible 402 body. Ticket // parameters are authenticated by the recipient HMAC. -func (e *PaymentEngine) MakeChallenge(ctx context.Context, runner, manifest string, payer ethcommon.Address, price int64, unit, service string) (Challenge, error) { +func (e *PaymentEngine) MakeChallenge(ctx context.Context, runner, manifest string, payer ethcommon.Address, price int64, unit, service string) (challenge Challenge, result error) { + labels := e.paymentLabels(runner, manifest) + defer func() { e.recordPayment("challenge", result, labels) }() + return e.makeChallenge(ctx, runner, manifest, payer, price, unit, service) +} + +func (e *PaymentEngine) makeChallenge(ctx context.Context, runner, manifest string, payer ethcommon.Address, price int64, unit, service string) (Challenge, error) { if runner == "" || manifest == "" || payer == (ethcommon.Address{}) || price <= 0 || (unit != "seconds" && unit != "fixed") { return Challenge{}, errors.New("invalid payment challenge scope") } @@ -105,7 +114,7 @@ func (e *PaymentEngine) MakeChallenge(ctx context.Context, runner, manifest stri current := e.sessions[manifest] if current == nil { if len(e.sessions) >= 100000 { - return Challenge{}, errors.New("payment session capacity reached") + return Challenge{}, errPaymentSessionCapacity } current = &paymentSession{runner: runner, payer: payer, price: priceInfo, unit: unit, balance: new(big.Rat)} e.sessions[manifest] = current @@ -140,7 +149,9 @@ func (e *PaymentEngine) ChallengeForManifest(runner, manifest, service string) ( return paymentChallenge(runner, manifest, service, current.info), nil } -func (e *PaymentEngine) RefreshChallenge(ctx context.Context, manifest string, payer ethcommon.Address, service string) (Challenge, error) { +func (e *PaymentEngine) RefreshChallenge(ctx context.Context, manifest string, payer ethcommon.Address, service string) (challenge Challenge, result error) { + labels := e.paymentLabels("", manifest) + defer func() { e.recordPayment("refresh", result, labels) }() e.mu.Lock() current := e.sessions[manifest] if current == nil { @@ -152,7 +163,7 @@ func (e *PaymentEngine) RefreshChallenge(ctx context.Context, manifest string, p if payer != expectedPayer { return Challenge{}, ErrInvalidPayment } - return e.MakeChallenge(ctx, runner, manifest, payer, price.PricePerUnit, unit, service) + return e.makeChallenge(ctx, runner, manifest, payer, price.PricePerUnit, unit, service) } func ManifestFromSegment(header string) (string, error) { @@ -171,6 +182,8 @@ var ErrInvalidPayment = errors.New("invalid payment") var ErrInsufficientBalance = errors.New("insufficient payment balance") var ErrMissingChallenge = errors.New("payment challenge not found") var ErrFixedAlreadyCharged = errors.New("fixed-price session already charged") +var errPaymentSessionCapacity = errors.New("payment session capacity reached") +var errPaymentTicketCapacity = errors.New("payment ticket capacity reached") func decodeHeaders(paymentHeader, segmentHeader string) (wire.Payment, wire.SegData, error) { paymentBytes, err := base64.StdEncoding.DecodeString(paymentHeader) @@ -192,7 +205,9 @@ func decodeHeaders(paymentHeader, segmentHeader string) (wire.Payment, wire.SegD return payment, segment, nil } -func (e *PaymentEngine) Receive(ctx context.Context, runner, manifest, paymentHeader, segmentHeader string) (ethcommon.Address, *big.Rat, error) { +func (e *PaymentEngine) Receive(ctx context.Context, runner, manifest, paymentHeader, segmentHeader string) (payerResult ethcommon.Address, credit *big.Rat, result error) { + labels := e.paymentLabels(runner, manifest) + defer func() { e.recordPayment("receive", result, labels) }() payment, segment, err := decodeHeaders(paymentHeader, segmentHeader) if err != nil { return ethcommon.Address{}, nil, err @@ -220,12 +235,12 @@ func (e *PaymentEngine) Receive(ctx context.Context, runner, manifest, paymentHe } funds, err := e.chain.PayerFunds(ctx, payer, e.recipient) if err != nil { - return ethcommon.Address{}, nil, err + return ethcommon.Address{}, nil, paymentObservation{err, "error"} } snapshot := funds.Snapshot active, err := e.chain.IsActiveAt(ctx, e.recipient, snapshot) if err != nil { - return ethcommon.Address{}, nil, err + return ethcommon.Address{}, nil, paymentObservation{err, "error"} } if !active { return ethcommon.Address{}, nil, ErrInvalidPayment @@ -235,7 +250,7 @@ func (e *PaymentEngine) Receive(ctx context.Context, runner, manifest, paymentHe return ethcommon.Address{}, nil, ErrInvalidPayment } if err := pm.ValidatePayerFunds(funds); err != nil { - return ethcommon.Address{}, nil, err + return ethcommon.Address{}, nil, paymentObservation{err, "rejected"} } if funds.Reserve.Cmp(params.FaceValue) < 0 || funds.Deposit.Cmp(params.FaceValue) < 0 { return ethcommon.Address{}, nil, pm.ErrPayerUnavailable @@ -252,7 +267,7 @@ func (e *PaymentEngine) Receive(ctx context.Context, runner, manifest, paymentHe return ethcommon.Address{}, nil, ErrInvalidPayment } if e.nonceCount+len(payment.PayerParams) > 1000000 { - return ethcommon.Address{}, nil, errors.New("payment ticket capacity reached") + return ethcommon.Address{}, nil, errPaymentTicketCapacity } randKey := recipientRand.String() previous := e.ticketNonces[randKey] @@ -288,11 +303,21 @@ func (e *PaymentEngine) Receive(ctx context.Context, runner, manifest, paymentHe previous.nonceSeen[nonce] = true } e.nonceCount += len(batchNonces) + e.metrics.Add("payment_credit_eth_total", observability.ETH(new(big.Rat).Sub(balance, session.balance)), labels) + e.metrics.Add("payment_tickets_total", float64(len(batchNonces)), labels.With("kind", "accepted")) + e.metrics.Add("payment_tickets_total", float64(len(winners)), labels.With("kind", "winning")) session.balance, session.updated = balance, time.Now() return payer, new(big.Rat).Set(balance), nil } -func (e *PaymentEngine) Charge(ctx context.Context, manifest string, now time.Time) error { +func (e *PaymentEngine) Charge(ctx context.Context, manifest string, now time.Time) (result error) { + labels := e.paymentLabels("", manifest) + observe := true + defer func() { + if observe { + e.recordPayment("charge", result, labels) + } + }() if err := ctx.Err(); err != nil { return err } @@ -306,6 +331,7 @@ func (e *PaymentEngine) Charge(ctx context.Context, manifest string, now time.Ti if current.unit == "fixed" { if !current.lastCharge.IsZero() { current.updated = time.Now() + observe = false return ErrFixedAlreadyCharged } units = 1 @@ -315,14 +341,26 @@ func (e *PaymentEngine) Charge(ctx context.Context, manifest string, now time.Ti return ErrInsufficientBalance } if units == 0 { + observe = false return nil } now = current.lastCharge.Add(time.Duration(units) * time.Second) } fee := new(big.Rat).Mul(big.NewRat(current.price.PricePerUnit, current.price.UnitsPerPrice), big.NewRat(units, 1)) + if units == 0 { + observe = false + } if current.balance.Cmp(fee) < 0 { return ErrInsufficientBalance } + e.metrics.Add("payment_charge_eth_total", observability.ETH(fee), labels) + if units > 0 { + if current.unit == "seconds" { + e.metrics.Add("payment_billed_seconds_total", float64(units), labels) + } else { + e.metrics.Add("payment_fixed_charges_total", float64(units), labels) + } + } current.balance.Sub(current.balance, fee) current.lastCharge, current.updated = now, time.Now() return nil diff --git a/orchestrator/payment_recipient_test.go b/orchestrator/payment_recipient_test.go index a17c8bf..fc34713 100644 --- a/orchestrator/payment_recipient_test.go +++ b/orchestrator/payment_recipient_test.go @@ -6,9 +6,13 @@ import ( "encoding/base64" "encoding/hex" "encoding/json" + "errors" "math/big" + "net/http/httptest" "os" "path/filepath" + "strconv" + "syscall" "testing" "time" @@ -16,6 +20,8 @@ import ( ethcommon "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" "github.com/livepeer/node/pm" "github.com/livepeer/node/pm/wire" "github.com/stretchr/testify/require" @@ -62,19 +68,25 @@ func TestRecipientHMACMatchesGoLivepeer(t *testing.T) { } type recipientTestChain struct { - block int64 - active bool + block int64 + active bool + snapshotErr, activeErr error + funds func(context.Context, pm.PayerFunds) (pm.PayerFunds, error) } func (c *recipientTestChain) Snapshot(context.Context) (pm.ChainSnapshot, error) { - return pm.ChainSnapshot{Block: big.NewInt(c.block), Round: big.NewInt(5), RoundHash: ethcommon.HexToHash("0x1234")}, nil + return pm.ChainSnapshot{Block: big.NewInt(c.block), Round: big.NewInt(5), RoundHash: ethcommon.HexToHash("0x1234")}, c.snapshotErr } func (c *recipientTestChain) IsActiveAt(context.Context, ethcommon.Address, pm.ChainSnapshot) (bool, error) { - return c.active, nil + return c.active, c.activeErr } func (c *recipientTestChain) PayerFunds(ctx context.Context, _, _ ethcommon.Address) (pm.PayerFunds, error) { snapshot, err := c.Snapshot(ctx) - return pm.PayerFunds{Snapshot: snapshot, Deposit: big.NewInt(1000000000), Reserve: big.NewInt(1000000000), WithdrawRound: new(big.Int)}, err + funds := pm.PayerFunds{Snapshot: snapshot, Deposit: big.NewInt(1000000000), Reserve: big.NewInt(1000000000), WithdrawRound: new(big.Int)} + if c.funds != nil { + return c.funds(ctx, funds) + } + return funds, err } func newRecipientTestEngine(t *testing.T) (*PaymentEngine, *recipientTestChain, *ecdsa.PrivateKey, string) { @@ -102,7 +114,7 @@ func issueRecipientParams(t *testing.T, e *PaymentEngine, key *ecdsa.PrivateKey) return info } -func receiveRecipientPayment(t *testing.T, e *PaymentEngine, key *ecdsa.PrivateKey, info wire.OrchestratorInfo, nonces ...uint32) error { +func recipientPayment(t *testing.T, key *ecdsa.PrivateKey, info wire.OrchestratorInfo, nonces ...uint32) (wire.Payment, wire.SegData) { t.Helper() payer := crypto.PubkeyToAddress(key.PublicKey) p := info.TicketParams @@ -122,17 +134,15 @@ func receiveRecipientPayment(t *testing.T, e *PaymentEngine, key *ecdsa.PrivateK hash := crypto.Keccak256(nil) flatten := append([]byte(info.Auth.SessionID), make([]byte, 32)...) flatten = append(flatten, hash...) - segment := wire.SegData{ManifestID: []byte(info.Auth.SessionID), Hash: hash, Signature: sign(flatten), Auth: info.Auth} - receive := func() error { - _, _, err := e.Receive(t.Context(), "runner", info.Auth.SessionID, base64.StdEncoding.EncodeToString(wire.EncodePayment(payment)), base64.StdEncoding.EncodeToString(wire.EncodeSegData(segment))) - return err - } - require.ErrorIs(t, receive(), ErrInvalidPayment, "unhashed credentials") - segment.Signature = sign(crypto.Keccak256(flatten)) - segment.Hash[0] ^= 1 - require.ErrorIs(t, receive(), ErrInvalidPayment, "tampered payload hash") - segment.Hash[0] ^= 1 - return receive() + segment := wire.SegData{ManifestID: []byte(info.Auth.SessionID), Hash: hash, Signature: sign(crypto.Keccak256(flatten)), Auth: info.Auth} + return payment, segment +} + +func receiveRecipientPayment(t *testing.T, e *PaymentEngine, key *ecdsa.PrivateKey, info wire.OrchestratorInfo, nonces ...uint32) error { + t.Helper() + payment, segment := recipientPayment(t, key, info, nonces...) + _, _, err := e.Receive(t.Context(), "runner", info.Auth.SessionID, base64.StdEncoding.EncodeToString(wire.EncodePayment(payment)), base64.StdEncoding.EncodeToString(wire.EncodeSegData(segment))) + return err } func TestRecipientHMACExpirationCopies(t *testing.T) { @@ -221,6 +231,7 @@ func TestRecipientHMACRejectsTamperedParameters(t *testing.T) { func TestRecipientBatchReplayAndExpiry(t *testing.T) { e, chain, key, _ := newRecipientTestEngine(t) + e.metrics = observability.New("orchestrator") info := issueRecipientParams(t, e, key) require.ErrorIs(t, receiveRecipientPayment(t, e, key, info, 1, 1), ErrInvalidPayment) balance, err := e.Balance("session") @@ -236,8 +247,11 @@ func TestRecipientBatchReplayAndExpiry(t *testing.T) { before, err := e.Balance("session") require.NoError(t, err) require.Positive(t, before.Sign(), "callers must not mutate accounting state") + challenges := test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "challenge"}) _, err = e.RefreshChallenge(t.Context(), "session", crypto.PubkeyToAddress(key.PublicKey), "https://orch.example") require.NoError(t, err) + require.Equal(t, challenges, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "challenge"})) + require.EqualValues(t, 1, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "refresh", "outcome": "success"})) // A newer valid auth token cannot reset nonce tracking for old PM params. info.Auth = e.authToken("session", time.Now().Add(2*time.Hour).Unix()) require.ErrorIs(t, receiveRecipientPayment(t, e, key, info, 1), ErrInvalidPayment) @@ -253,6 +267,8 @@ func TestRecipientBatchReplayAndExpiry(t *testing.T) { require.ErrorIs(t, receiveRecipientPayment(t, e, key, info, 1), ErrInvalidPayment, "a backward observation cannot revive pruned replay state") newInfo := issueRecipientParams(t, e, key) require.NoError(t, receiveRecipientPayment(t, e, key, newInfo, 1)) + require.EqualValues(t, 3, test.MetricSum(t, e.metrics.Registry, "payment_tickets_total", map[string]string{"kind": "accepted"})) + require.EqualValues(t, 3, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "receive", "outcome": "success"})) } func TestRecipientRestartRotatesSecretsAndPreservesWinningTickets(t *testing.T) { @@ -312,11 +328,14 @@ func TestRecipientRejectsParametersOnceRedemptionPrepared(t *testing.T) { func TestRecipientStorageFailureDoesNotPublishCreditOrConsumeNonces(t *testing.T) { e, _, key, _ := newRecipientTestEngine(t) + e.metrics = observability.New("orchestrator") info := issueRecipientParams(t, e, key) _, err := e.store.db.Exec(`CREATE TRIGGER reject_second_ticket BEFORE INSERT ON winning_tickets WHEN NEW.ticket_nonce=2 BEGIN SELECT RAISE(ABORT, 'storage failure'); END`) require.NoError(t, err) require.ErrorContains(t, receiveRecipientPayment(t, e, key, info, 1, 2), "storage failure") + require.EqualValues(t, 1, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "receive", "outcome": "error"})) + require.Zero(t, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "receive", "outcome": "success"})) count, err := e.store.WinningTicketCount(crypto.PubkeyToAddress(key.PublicKey), 0) require.NoError(t, err) require.Zero(t, count, "partial inserts must roll back") @@ -331,3 +350,124 @@ func TestRecipientStorageFailureDoesNotPublishCreditOrConsumeNonces(t *testing.T require.NoError(t, err) require.Equal(t, 2, count) } + +func TestPaidFailureOutcomes(t *testing.T) { + for _, cause := range []string{ + "funding", "withdrawal", "face_value", "liability", "capacity", "rpc", "storage", + "cancelled", "unhashed segment", "tampered hash", "challenge snapshot", + "challenge active", "challenge cancelled", "challenge timeout", "challenge capacity", + } { + t.Run(cause, func(t *testing.T) { + e, chain, key, _ := newRecipientTestEngine(t) + registry, server := reviewServer(t, "http://127.0.0.1:1") + defer server.Close() + registry.SetWeiPerUSD(big.NewRat(1, 1)) + require.NoError(t, registry.AddStatic(StaticRunner{ID: "runner", App: "model", Mode: "single-shot", RunnerURL: "http://127.0.0.1:1", Capacity: 1, PriceInfo: priceInfo{Price: "9", Currency: "usd", Unit: "fixed"}})) + server.SetPayment(e) + info := issueRecipientParams(t, e, key) + nonces := []uint32{1} + operation, outcome, appOutcome := "receive", "rejected", "rejected" + switch cause { + case "capacity": + e.nonceCount = 1000000 + outcome, appOutcome = "capacity", "capacity" + case "rpc", "storage": + outcome, appOutcome = "error", "error" + case "cancelled": + outcome, appOutcome = "cancelled", "client_cancelled" + case "challenge capacity": + for n := range 100000 { + e.sessions[strconv.Itoa(n)] = nil + } + operation, outcome, appOutcome = "challenge", "capacity", "capacity" + case "challenge snapshot": + chain.snapshotErr = syscall.ECONNREFUSED + operation, outcome, appOutcome = "challenge", "connection_refused", "error" + case "challenge active": + chain.activeErr = errors.New("RPC unavailable") + operation, outcome, appOutcome = "challenge", "error", "error" + case "challenge cancelled": + chain.snapshotErr = context.Canceled + operation, outcome, appOutcome = "challenge", "cancelled", "client_cancelled" + case "challenge timeout": + chain.snapshotErr = context.DeadlineExceeded + operation, outcome, appOutcome = "challenge", "timeout", "error" + case "liability": + require.NoError(t, receiveRecipientPayment(t, e, key, info, 1)) + nonces = []uint32{2, 3} + } + chain.funds = func(ctx context.Context, funds pm.PayerFunds) (pm.PayerFunds, error) { + switch cause { + case "funding": + funds.Reserve.SetInt64(0) + case "withdrawal": + funds.WithdrawRound.Set(funds.Snapshot.Round) + case "face_value": + funds.Deposit.SetInt64(1) + case "liability": + funds.Deposit.SetInt64(10) + funds.Reserve.SetInt64(10) + case "rpc": + return pm.PayerFunds{}, errors.New("RPC unavailable") + case "cancelled": + return pm.PayerFunds{}, ctx.Err() + } + return funds, nil + } + if cause == "storage" { + _, err := e.store.db.Exec(`CREATE TRIGGER reject_ticket BEFORE INSERT ON winning_tickets BEGIN SELECT RAISE(ABORT,'storage failure'); END`) + require.NoError(t, err) + } + status := 400 + request := httptest.NewRequest("POST", "/apps/runner/app", nil) + if operation == "receive" { + payment, segment := recipientPayment(t, key, info, nonces...) + if cause == "unhashed segment" { + flatten := append(append([]byte(info.Auth.SessionID), make([]byte, 32)...), segment.Hash...) + signature, err := crypto.Sign(accounts.TextHash(flatten), key) + require.NoError(t, err) + signature[64] += 27 + segment.Signature, status = signature, 403 + } else if cause == "tampered hash" { + segment.Hash[0] ^= 1 + status = 403 + } + request.Header.Set("Livepeer-Payment", base64.StdEncoding.EncodeToString(wire.EncodePayment(payment))) + request.Header.Set("Livepeer-Segment", base64.StdEncoding.EncodeToString(wire.EncodeSegData(segment))) + } else { + status = 502 + request.Header.Set("Livepeer-Payer-Address", crypto.PubkeyToAddress(key.PublicKey).Hex()) + } + if cause == "cancelled" { + ctx, cancel := context.WithCancel(t.Context()) + cancel() + request = request.WithContext(ctx) + } + response := httptest.NewRecorder() + server.ServeHTTP(response, request) + require.Equal(t, status, response.Code, response.Body.String()) + require.EqualValues(t, 1, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": operation, "outcome": outcome})) + require.EqualValues(t, 1, test.MetricSum(t, e.metrics.Registry, "app_calls_total", map[string]string{"outcome": appOutcome})) + require.Zero(t, test.MetricSum(t, e.metrics.Registry, "upstream_requests_total", nil)) + }) + } + +} + +func TestLiveChargeObservesOnlyDebitAttempts(t *testing.T) { + e, _, key, _ := newRecipientTestEngine(t) + e.metrics = observability.New("orchestrator") + _, err := e.MakeChallenge(t.Context(), "runner", "session", crypto.PubkeyToAddress(key.PublicKey), 9, "seconds", "https://orch.example") + require.NoError(t, err) + e.sessions["session"].balance.SetInt64(18) + now := time.Now() + require.NoError(t, e.Charge(t.Context(), "session", now)) + for range 3 { + require.NoError(t, e.Charge(t.Context(), "session", now.Add(100*time.Millisecond))) + } + require.Zero(t, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "charge"})) + require.NoError(t, e.Charge(t.Context(), "session", now.Add(time.Second))) + require.ErrorIs(t, e.Charge(t.Context(), "session", now.Add(3*time.Second)), ErrInsufficientBalance) + require.EqualValues(t, 1, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "charge", "outcome": "success"})) + require.EqualValues(t, 1, test.MetricSum(t, e.metrics.Registry, "payment_operations_total", map[string]string{"operation": "charge", "outcome": "insufficient_balance"})) +} diff --git a/orchestrator/payment_test.go b/orchestrator/payment_test.go index 19c4855..ac5ff52 100644 --- a/orchestrator/payment_test.go +++ b/orchestrator/payment_test.go @@ -130,6 +130,13 @@ func TestPaidFixedSessionWithRemoteSigner(t *testing.T) { followup := httptest.NewRequest(http.MethodPost, challenge.PaymentURL, nil) server.ServeHTTP(w, followup) require.Equal(t, 409, w.Code) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "payment_tickets_total", map[string]string{"kind": "accepted"})) + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "payment_fixed_charges_total", map[string]string{"app": "demo"})) + for range 3 { + server.ChargePaidSessions(t.Context()) + } + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "payment_operations_total", map[string]string{"operation": "charge"}), "scheduler ticks must not count another fixed-price debit") + require.EqualValues(t, 1, test.MetricSum(t, registry.metrics.Registry, "payment_operations_total", map[string]string{"operation": "receive", "outcome": "success"})) } func TestPinnedPythonPaidSingleShot(t *testing.T) { diff --git a/orchestrator/pending_test.go b/orchestrator/pending_test.go index 1b2fb74..e96042c 100644 --- a/orchestrator/pending_test.go +++ b/orchestrator/pending_test.go @@ -5,6 +5,7 @@ import ( "testing" "time" + "github.com/livepeer/node/internal/test" "github.com/stretchr/testify/require" ) @@ -41,4 +42,21 @@ func TestPendingPaymentDoesNotExposeOrBillSession(t *testing.T) { require.Equal(t, token, reservedToken) r.ReleaseBySession(id) require.False(t, r.activateSession("r", id), "a released pending reservation cannot be resurrected") + for _, reason := range []string{"shutdown", "runner_expired", "runner_unregistered", "runner_unhealthy", "completed", "released", ""} { + id, _, _, _, err := r.reserveWithPrice("r", "pending-"+reason, "e) + require.NoError(t, err) + want := reason + if reason == "completed" || reason == "released" || reason == "" { + want = "reservation_failed" + } + before := test.MetricSum(t, r.metrics.Registry, "session_ends_total", map[string]string{"reason": want}) + if reason == "" { + r.ReleaseBySession(id) + } else { + r.ReleaseBySession(id, reason) + } + require.Equal(t, before+1, test.MetricSum(t, r.metrics.Registry, "session_ends_total", map[string]string{"reason": want})) + } + require.EqualValues(t, 1, test.MetricSum(t, r.metrics.Registry, "session_duration_seconds", nil), "only the activated session contributes duration") + } diff --git a/orchestrator/pricing_test.go b/orchestrator/pricing_test.go index 048b1a1..fb5198d 100644 --- a/orchestrator/pricing_test.go +++ b/orchestrator/pricing_test.go @@ -8,6 +8,7 @@ import ( "testing/synctest" "time" + "github.com/livepeer/node/internal/test" "github.com/stretchr/testify/require" ) @@ -53,5 +54,6 @@ func TestFeedUpdatesOnlyNewSessionPricesAndFailsClosedWhenStale(t *testing.T) { require.NoError(t, err, "existing agreed prices must survive feed outages") r.SetWeiPerUSD(big.NewRat(10800, 1)) require.Len(t, r.Discovery()[0].Runners, 1) + require.Zero(t, test.MetricSum(t, r.metrics.Registry, "price_feed_updates_total", nil), "setting a rate is not a feed read") }) } diff --git a/orchestrator/redeemer.go b/orchestrator/redeemer.go index c96db13..8215d5a 100644 --- a/orchestrator/redeemer.go +++ b/orchestrator/redeemer.go @@ -107,7 +107,12 @@ func (s *RedeemerDB) setTicketPhase(ctx context.Context, sig []byte, phase strin if terminalRedemption(phase) { return s.finishTicket(ctx, sig, phase, "") } - _, err := s.db.ExecContext(ctx, `INSERT INTO redemption_attempts(sig,attempted_at,phase) VALUES(?,?,?) ON CONFLICT(sig) DO UPDATE SET phase=excluded.phase WHERE redemption_attempts.phase IN ('retryable','awaiting_finality')`, sig, time.Now().UTC().Format(time.RFC3339Nano), phase) + result, err := s.db.ExecContext(ctx, `INSERT INTO redemption_attempts(sig,attempted_at,phase) VALUES(?,?,?) ON CONFLICT(sig) DO UPDATE SET phase=excluded.phase WHERE redemption_attempts.phase IN ('retryable','awaiting_finality') AND redemption_attempts.phase!=excluded.phase`, sig, time.Now().UTC().Format(time.RFC3339Nano), phase) + if err == nil { + if n, _ := result.RowsAffected(); n > 0 { + s.observeTransition(phase, "", nil) + } + } return err } diff --git a/orchestrator/redeemer_db.go b/orchestrator/redeemer_db.go index 1c37680..c20f425 100644 --- a/orchestrator/redeemer_db.go +++ b/orchestrator/redeemer_db.go @@ -10,14 +10,17 @@ import ( "errors" "fmt" "io/fs" + "log/slog" "math/big" "net/url" "os" "path/filepath" "strings" "sync" + "time" ethcommon "github.com/ethereum/go-ethereum/common" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/nodeconfig/migrations" "github.com/livepeer/node/pm" _ "modernc.org/sqlite" @@ -29,6 +32,9 @@ var redeemerMigrationFiles embed.FS // RedeemerDB owns the orchestrator redeemer's durable winning-ticket queue, // redemption lifecycle, and chain activity observations. type RedeemerDB struct { + logger *slog.Logger + metrics *observability.Metrics + readiness *paidReadiness db *sql.DB recoveryMu sync.Mutex recovery *redemptionRecovery @@ -113,10 +119,10 @@ func (s *RedeemerDB) StoreWinningTicket(t *pm.SignedTicket) error { return err } _, err := s.db.Exec(`INSERT INTO winning_tickets - (payer_address,recipient,face_value,win_prob,ticket_nonce,recipient_rand,recipient_rand_hash,sig,creation_round,creation_round_block_hash,params_expiration_block) - VALUES(?,?,?,?,?,?,?,?,?,?,?)`, t.PayerAddress.Hex(), t.Recipient.Hex(), t.FaceValue.Bytes(), t.WinProb.Bytes(), + (payer_address,recipient,face_value,win_prob,ticket_nonce,recipient_rand,recipient_rand_hash,sig,creation_round,creation_round_block_hash,params_expiration_block,enqueued_at) + VALUES(?,?,?,?,?,?,?,?,?,?,?,?)`, t.PayerAddress.Hex(), t.Recipient.Hex(), t.FaceValue.Bytes(), t.WinProb.Bytes(), t.TicketNonce, t.RecipientRand.Bytes(), t.RecipientRandHash.Hex(), t.Sig, t.CreationRound, - t.CreationRoundBlockHash.Hex(), t.ParamsExpirationBlock.String()) + t.CreationRoundBlockHash.Hex(), t.ParamsExpirationBlock.String(), time.Now().UTC().Format(time.RFC3339Nano)) return err } @@ -139,8 +145,8 @@ func (s *RedeemerDB) storeWinningTickets(ctx context.Context, payer ethcommon.Ad return ErrInvalidPayment } for _, ticket := range tickets { - _, err := tx.Exec(`INSERT INTO winning_tickets(payer_address,recipient,face_value,win_prob,ticket_nonce,recipient_rand,recipient_rand_hash,sig,creation_round,creation_round_block_hash,params_expiration_block) - VALUES(?,?,?,?,?,?,?,?,?,?,?)`, payer.Hex(), ticket.Recipient.Hex(), ticket.FaceValue.Bytes(), ticket.WinProb.Bytes(), ticket.TicketNonce, ethcommon.LeftPadBytes(ticket.RecipientRand.Bytes(), 32), ticket.RecipientRandHash.Hex(), ticket.Sig, ticket.CreationRound, ticket.CreationRoundBlockHash.Hex(), ticket.ParamsExpirationBlock.String()) + _, err := tx.Exec(`INSERT INTO winning_tickets(payer_address,recipient,face_value,win_prob,ticket_nonce,recipient_rand,recipient_rand_hash,sig,creation_round,creation_round_block_hash,params_expiration_block,enqueued_at) + VALUES(?,?,?,?,?,?,?,?,?,?,?,?)`, payer.Hex(), ticket.Recipient.Hex(), ticket.FaceValue.Bytes(), ticket.WinProb.Bytes(), ticket.TicketNonce, ethcommon.LeftPadBytes(ticket.RecipientRand.Bytes(), 32), ticket.RecipientRandHash.Hex(), ticket.Sig, ticket.CreationRound, ticket.CreationRoundBlockHash.Hex(), ticket.ParamsExpirationBlock.String(), time.Now().UTC().Format(time.RFC3339Nano)) if err != nil { return err } diff --git a/orchestrator/redeemer_db_test.go b/orchestrator/redeemer_db_test.go index c1372e9..26cf461 100644 --- a/orchestrator/redeemer_db_test.go +++ b/orchestrator/redeemer_db_test.go @@ -120,6 +120,7 @@ func TestRedemptionMigrationHistoryAndRollback(t *testing.T) { files, err := fs.Sub(redeemerMigrationFiles, "migrations") require.NoError(t, err) require.NoError(t, migrations.Down(t.Context(), s.db, files)) + require.NoError(t, migrations.Down(t.Context(), s.db, files)) // Seed a genuine v1 database, then upgrade without changing its ticket identity. prepared, err := c.PrepareRedemption(t.Context(), key, big.NewInt(1), redeemTicket(ticket)) require.NoError(t, err) @@ -127,12 +128,19 @@ func TestRedemptionMigrationHistoryAndRollback(t *testing.T) { require.NoError(t, err) _, err = s.db.Exec("UPDATE winning_tickets SET tx_hash=? WHERE sig=?", prepared.Hash.Hex(), ticket.Sig) require.NoError(t, err) + backfillStart := time.Now().Add(-time.Second) require.NoError(t, migrations.Up(t.Context(), s.db, files)) + var enqueued string + require.NoError(t, s.db.QueryRow("SELECT enqueued_at FROM winning_tickets WHERE sig=?", ticket.Sig).Scan(&enqueued)) + enqueuedAt, err := time.Parse(time.RFC3339Nano, enqueued) + require.NoError(t, err) + require.WithinRange(t, enqueuedAt, backfillStart, time.Now()) history, err := s.Redemptions() require.NoError(t, err) require.Equal(t, []RedemptionStatus{{Hash: prepared.Hash.Hex(), Phase: "submitted"}}, history) // A lossless rollback remains possible with the original representable state. require.NoError(t, migrations.Down(t.Context(), s.db, files)) + require.NoError(t, migrations.Down(t.Context(), s.db, files)) require.NoError(t, migrations.Up(t.Context(), s.db, files)) _, err = s.db.Exec("UPDATE redemption_attempts SET phase='retryable' WHERE sig=?", ticket.Sig) require.NoError(t, err) @@ -140,6 +148,7 @@ func TestRedemptionMigrationHistoryAndRollback(t *testing.T) { next.Hash = ethcommon.HexToHash("0xabcdef") next.Nonce = 1 require.NoError(t, s.recordPrepared(t.Context(), ticket, next)) + require.NoError(t, migrations.Down(t.Context(), s.db, files)) require.ErrorContains(t, migrations.Down(t.Context(), s.db, files), "cannot_downgrade_redemption_transaction_history") history, err = s.Redemptions() require.NoError(t, err) @@ -160,6 +169,7 @@ func TestRedemptionRollbackPreservesTransactionProgress(t *testing.T) { require.EqualValues(t, 1, floor) files, err := fs.Sub(redeemerMigrationFiles, "migrations") require.NoError(t, err) + require.NoError(t, migrations.Down(t.Context(), s.db, files)) require.ErrorContains(t, migrations.Down(t.Context(), s.db, files), "cannot_downgrade_redemption_transaction_history") floor, err = s.SavedNonceFloor(t.Context(), key.Address()) require.NoError(t, err) diff --git a/orchestrator/redemption_metrics.go b/orchestrator/redemption_metrics.go new file mode 100644 index 0000000..2a1800b --- /dev/null +++ b/orchestrator/redemption_metrics.go @@ -0,0 +1,173 @@ +package orchestrator + +import ( + "context" + "database/sql" + "errors" + "fmt" + "math/big" + "time" + + "github.com/livepeer/node/internal/observability" +) + +// observeTransition is called only after a durable change commits. Callback +// failures are counted here because they do not necessarily reach the poller. +func (s *RedeemerDB) observeTransition(phase, hash string, err error) { + s.metrics.Add("redemption_transitions_total", 1, observability.Labels{"event": phase}) + if err != nil { + s.metrics.Add("redemption_errors_total", 1, observability.Labels{"error_kind": observability.ErrorKind(err)}) + } + if s.logger != nil { + s.logger.Info("redemption state changed", "event", "redemption_transition", "operation", "redeem", "outcome", phase, "transaction_hash", hash, "error_kind", observability.ErrorKind(err)) + } +} + +// collectMetrics uses a read transaction so tickets and replacement identities +// describe one durable snapshot. The caller never probes the chain. +func (s *RedeemerDB) collectMetrics(emit observability.Emit) { + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() + stats, err := s.redemptionStats(ctx) + emit("collector_healthy", observability.Bool(err == nil), observability.Labels{"collector": "redemptions"}) + if err != nil { + return + } + for state, count := range stats.tickets { + emit("redemption_queue_tickets", float64(count), observability.Labels{"state": state}) + } + for state, at := range stats.oldestTickets { + emit("redemption_oldest_ticket_timestamp_seconds", at, observability.Labels{"state": state}) + } + for phase, count := range stats.transactions { + emit("redemption_unresolved_transactions", float64(count), observability.Labels{"phase": phase}) + } + for phase, at := range stats.oldestTransactions { + emit("redemption_oldest_transaction_timestamp_seconds", at, observability.Labels{"phase": phase}) + } + emit("redemption_last_settlement_timestamp_seconds", stats.lastSettlement, nil) +} + +type redemptionStats struct { + tickets, transactions map[string]int + oldestTickets, oldestTransactions map[string]float64 + lastSettlement float64 +} + +func (s *RedeemerDB) redemptionStats(ctx context.Context) (stats redemptionStats, err error) { + stats = redemptionStats{tickets: map[string]int{"waiting": 0, "eligible": 0, "in_flight": 0, "awaiting_finality": 0, "unknown": 0}, transactions: map[string]int{}, oldestTickets: map[string]float64{}, oldestTransactions: map[string]float64{}} + for state := range stats.tickets { + stats.oldestTickets[state] = 0 + } + for _, phase := range []string{"prepared", "broadcast", "submitted", "mined", "retryable", "used", "expired", "invalid", "unknown"} { + stats.transactions[phase] = 0 + stats.oldestTransactions[phase] = 0 + } + tx, err := s.db.BeginTx(ctx, &sql.TxOptions{ReadOnly: true}) + if err != nil { + return stats, err + } + defer tx.Rollback() + // A cached protocol snapshot only determines clock eligibility; unavailable + // or stale clocks are reported as unknown instead of fabricating zero work. + var block, round *big.Int + if s.readiness != nil { + s.readiness.mu.Lock() + if time.Since(s.readiness.completed) <= max(time.Minute, 3*s.readiness.interval) && s.readiness.chain { + block, round = s.readiness.snapshot.Block, s.readiness.snapshot.Round + } + s.readiness.mu.Unlock() + } + rows, err := tx.QueryContext(ctx, `SELECT COALESCE(w.enqueued_at,''),w.params_expiration_block,w.creation_round,COALESCE(a.phase,'') FROM winning_tickets w LEFT JOIN redemption_attempts a ON a.sig=w.sig WHERE w.redeemed_at IS NULL AND COALESCE(a.phase,'') NOT IN ('confirmed','used','expired','invalid','reverted')`) + if err != nil { + return stats, err + } + for rows.Next() { + var at, expiry, phase string + var creation int64 + if err = rows.Scan(&at, &expiry, &creation, &phase); err != nil { + break + } + state := "unknown" + switch phase { + case "prepared", "broadcast", "sending", "submitted", "mined": + state = "in_flight" + case "awaiting_finality": + state = "awaiting_finality" + default: + if block != nil && round != nil { + end, ok := new(big.Int).SetString(expiry, 10) + if !ok { + rows.Close() + return stats, fmt.Errorf("invalid ticket expiry") + } + if creation < round.Int64()-2 { + continue + } + state = "eligible" + if end.Cmp(block) > 0 { + state = "waiting" + } + } + } + stats.tickets[state]++ + if err = recordOldest(stats.oldestTickets, state, at); err != nil { + break + } + } + err = errors.Join(err, rows.Err(), rows.Close()) + if err != nil { + return stats, err + } + rows, err = tx.QueryContext(ctx, `SELECT t.phase,t.prepared_at FROM redemption_transactions t JOIN redemption_attempts a ON a.sig=t.sig WHERE a.phase NOT IN ('confirmed','used') AND t.phase NOT IN ('confirmed','reverted','superseded')`) + if err != nil { + return stats, err + } + for rows.Next() { + var phase, at string + if err = rows.Scan(&phase, &at); err != nil { + break + } + if phase == "sending" { + phase = "broadcast" + } + switch phase { + case "prepared", "broadcast", "submitted", "mined", "retryable", "used", "expired", "invalid": + default: + phase = "unknown" + } + stats.transactions[phase]++ + if err = recordOldest(stats.oldestTransactions, phase, at); err != nil { + break + } + } + err = errors.Join(err, rows.Err(), rows.Close()) + if err != nil { + return stats, err + } + var last sql.NullString + if err = tx.QueryRowContext(ctx, `SELECT MAX(redeemed_at) FROM winning_tickets`).Scan(&last); err != nil { + return stats, err + } + if last.Valid { + var at time.Time + at, err = time.Parse(time.RFC3339Nano, last.String) + stats.lastSettlement = float64(at.Unix()) + } + return stats, err +} + +func recordOldest(values map[string]float64, key, raw string) error { + if raw == "" { + return nil + } + at, err := time.Parse(time.RFC3339Nano, raw) + if err != nil { + return err + } + n := float64(at.Unix()) + if values[key] == 0 || n < values[key] { + values[key] = n + } + return nil +} diff --git a/orchestrator/redemption_nonce.go b/orchestrator/redemption_nonce.go index 6ea7f54..4d62b89 100644 --- a/orchestrator/redemption_nonce.go +++ b/orchestrator/redemption_nonce.go @@ -2,6 +2,7 @@ package orchestrator import ( "context" + "database/sql" "errors" "fmt" "strconv" @@ -156,11 +157,12 @@ func (s *RedeemerDB) reconcileFinalizedNonces(ctx context.Context, chain finaliz } continue } + var retryResult sql.Result tx, err := s.db.BeginTx(ctx, nil) if err == nil { _, err = tx.ExecContext(ctx, `UPDATE redemption_transactions SET phase='superseded',error=NULL WHERE hash=? AND phase NOT IN ('confirmed','reverted','superseded')`, item.hash.Hex()) if err == nil { - _, err = tx.ExecContext(ctx, `UPDATE redemption_attempts SET phase='retryable',error=NULL WHERE phase IN ('prepared','broadcast','submitted','mined') AND sig IN (SELECT sig FROM winning_tickets WHERE tx_hash=?)`, item.hash.Hex()) + retryResult, err = tx.ExecContext(ctx, `UPDATE redemption_attempts SET phase='retryable',error=NULL WHERE phase IN ('prepared','broadcast','submitted','mined') AND sig IN (SELECT sig FROM winning_tickets WHERE tx_hash=?)`, item.hash.Hex()) } if err == nil { err = tx.Commit() @@ -169,6 +171,10 @@ func (s *RedeemerDB) reconcileFinalizedNonces(ctx context.Context, chain finaliz } if err != nil { failures = append(failures, err) + } else if retryResult != nil { + if n, _ := retryResult.RowsAffected(); n > 0 { + s.observeTransition("retryable", item.hash.Hex(), nil) + } } } } diff --git a/orchestrator/redemption_recovery.go b/orchestrator/redemption_recovery.go index 3f449ba..9684e9d 100644 --- a/orchestrator/redemption_recovery.go +++ b/orchestrator/redemption_recovery.go @@ -206,19 +206,35 @@ func (r *redemptionRecovery) recordResult(ctx context.Context, result *eth.Trans return err } defer tx.Rollback() + var transactionResult sql.Result if phase == "mined" && result.TxHash != (common.Hash{}) { - _, err = tx.ExecContext(ctx, `UPDATE redemption_transactions SET phase='mined',error=NULL,acknowledged=1 WHERE hash=? AND phase NOT IN ('confirmed','reverted','superseded')`, result.TxHash.Hex()) + transactionResult, err = tx.ExecContext(ctx, `UPDATE redemption_transactions SET phase='mined',error=NULL,acknowledged=1 WHERE hash=? AND phase NOT IN ('confirmed','reverted','superseded') AND (phase!='mined' OR acknowledged!=1 OR error IS NOT NULL)`, result.TxHash.Hex()) } else if phase == "retryable" { - _, err = tx.ExecContext(ctx, `UPDATE redemption_transactions SET phase=?,error=? WHERE root_hash=? AND phase IN ('prepared','broadcast','sending','submitted','mined')`, phase, message, root) + transactionResult, err = tx.ExecContext(ctx, `UPDATE redemption_transactions SET phase=?,error=? WHERE root_hash=? AND phase IN ('prepared','broadcast','sending','submitted','mined')`, phase, message, root) } if err != nil { return err } - _, err = tx.ExecContext(ctx, `UPDATE redemption_attempts SET phase=?,error=? WHERE phase IN ('prepared','broadcast','submitted','mined') AND sig IN (SELECT sig FROM redemption_transactions WHERE root_hash=?) AND EXISTS(SELECT 1 FROM winning_tickets w JOIN redemption_transactions t ON t.hash=w.tx_hash WHERE w.sig=redemption_attempts.sig AND t.root_hash=?)`, phase, message, root, root) + summaryResult, err := tx.ExecContext(ctx, `UPDATE redemption_attempts SET phase=?,error=? WHERE phase IN ('prepared','broadcast','submitted','mined') AND (phase!=? OR error IS NOT ?) AND sig IN (SELECT sig FROM redemption_transactions WHERE root_hash=?) AND EXISTS(SELECT 1 FROM winning_tickets w JOIN redemption_transactions t ON t.hash=w.tx_hash WHERE w.sig=redemption_attempts.sig AND t.root_hash=?)`, phase, message, phase, message, root, root) if err != nil { return err } - return tx.Commit() + if err := tx.Commit(); err != nil { + return err + } + changed, _ := summaryResult.RowsAffected() + if transactionResult != nil { + n, _ := transactionResult.RowsAffected() + changed += n + } + if changed > 0 { + var failure error + if phase == "retryable" { + failure = result.Error() + } + r.store.observeTransition(phase, result.OriginHash().Hex(), failure) + } + return nil } func terminalRedemption(phase string) bool { diff --git a/orchestrator/redemption_recovery_test.go b/orchestrator/redemption_recovery_test.go index f77cd4a..7db0a03 100644 --- a/orchestrator/redemption_recovery_test.go +++ b/orchestrator/redemption_recovery_test.go @@ -1,6 +1,7 @@ package orchestrator import ( + "context" "encoding/hex" "encoding/json" "fmt" @@ -17,6 +18,7 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/crypto" "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/internal/test" "github.com/livepeer/node/pm" "github.com/stretchr/testify/require" @@ -414,6 +416,7 @@ func TestRedemptionReplacementFailuresRemainQueued(t *testing.T) { for _, scenario := range []string{"limit", "ceiling", "rejection", "persistence"} { t.Run(scenario, func(t *testing.T) { f, s, ticket, c, key := newRecoveryTest(t, 6) + s.metrics = observability.New("orchestrator") options := RedemptionOptions{Timeout: 30 * time.Millisecond, MaxReplacements: 1} if scenario == "limit" { options.MaxReplacements = 0 @@ -430,6 +433,7 @@ func TestRedemptionReplacementFailuresRemainQueued(t *testing.T) { require.NoError(t, err) } require.NoError(t, StartRedemptionRecovery(t.Context(), s, c, key, options)) + nextResult := captureRecoveryResults(t, s) tickRecovery(t, s, c, key) require.Eventually(t, func() bool { return ticketPhase(t, s, ticket.Sig) == "retryable" }, time.Second, 5*time.Millisecond) expected := 1 @@ -446,6 +450,16 @@ func TestRedemptionReplacementFailuresRemainQueued(t *testing.T) { var redeemed *string require.NoError(t, s.db.QueryRow("SELECT redeemed_at FROM winning_tickets WHERE sig=?", ticket.Sig).Scan(&redeemed)) require.Nil(t, redeemed) + result := nextResult() + require.Error(t, result.Error()) + // A rejected replacement commits retryable before the callback moves + // the still-submitted predecessor into retryable as well. + require.EqualValues(t, expected, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"})) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_errors_total", nil)) + require.NoError(t, s.recovery.recordResult(t.Context(), result)) + require.EqualValues(t, expected, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"}), "replaying a completed callback must not emit another transition") + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_errors_total", nil), "replaying a completed callback must not emit another failure") + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "redemption_settlements_total", nil)) }) } } @@ -473,16 +487,21 @@ func TestLostResponseUsesFinalizedTicketGuard(t *testing.T) { func TestUsedTicketGuardRecoversAfterReorg(t *testing.T) { f, s, ticket, c, key := newRecoveryTest(t, 8) + s.metrics = observability.New("orchestrator") f.finalized = false f.used[ticket.Hash()] = true tickRecovery(t, s, c, key) require.Equal(t, "awaiting_finality", ticketPhase(t, s, ticket.Sig)) require.Empty(t, f.transactions()) + tickRecovery(t, s, c, key) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "awaiting_finality"})) f.mu.Lock() delete(f.used, ticket.Hash()) f.mu.Unlock() tickRecovery(t, s, c, key) require.Len(t, f.transactions(), 1) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"})) + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "redemption_errors_total", nil), "a reorg is not a service failure") } func reopenRecoveryStore(t *testing.T, s *RedeemerDB) *RedeemerDB { @@ -856,8 +875,11 @@ func TestRevertedReplacementReleasesSameNonceLiability(t *testing.T) { func TestManualRetryFailureKeepsActiveMonitor(t *testing.T) { f, s, ticket, c, key := newRecoveryTest(t, 101) + s.metrics = observability.New("orchestrator") require.NoError(t, StartRedemptionRecovery(t.Context(), s, c, key, RedemptionOptions{Timeout: time.Hour, MaxReplacements: 1})) tickRecovery(t, s, c, key) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "broadcast"})) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "submitted"})) first := f.transactions()[0] f.mu.Lock() f.rejectNext = true @@ -871,11 +893,14 @@ func TestManualRetryFailureKeepsActiveMonitor(t *testing.T) { s.recovery.mu.Unlock() require.Equal(t, 1, roots) require.Len(t, sent, 2, "an identical-byte manual retry must not admit a fresh nonce while the original monitor is active") + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "broadcast"})) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "submitted"})) } func TestConsumedNonceResolvesOtherTicketHistory(t *testing.T) { f := newRecoveryRPC(t) s, a := f.store(t, 103) + s.metrics = observability.New("orchestrator") ca, cb, key := f.chain(t), f.chain(t), recoveryKey(t) b := nextRecoveryTicket(a, 104) b.PayerAddress = common.HexToAddress("0x9999") @@ -887,6 +912,7 @@ func TestConsumedNonceResolvesOtherTicketHistory(t *testing.T) { f.rejectNext = true f.mu.Unlock() require.Error(t, broadcastRedemption(t.Context(), s, ca.Contracts, a.Sig, a0)) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"})) b0, err := cb.PrepareRedemption(t.Context(), key, big.NewInt(1), redeemTicket(b)) require.NoError(t, err) require.Equal(t, a0.Nonce, b0.Nonce) @@ -897,12 +923,24 @@ func TestConsumedNonceResolvesOtherTicketHistory(t *testing.T) { require.EqualValues(t, 1, a1.Nonce) require.NoError(t, s.recordPrepared(t.Context(), a, a1)) require.NoError(t, broadcastRedemption(t.Context(), s, ca.Contracts, a.Sig, a1)) + // A durable sibling on the same sender/nonce must become retryable when B + // finalizes, even though the sibling itself has no finalized receipt. + sibling := nextRecoveryTicket(a, 108) + require.NoError(t, s.StoreWinningTicket(sibling)) + require.NoError(t, s.recordPrepared(t.Context(), sibling, eth.SignedTransaction{Hash: common.HexToHash("0xc"), Raw: []byte{1}, From: b0.From, Nonce: b0.Nonce})) sent := f.transactions() f.mine(sent[1], true) f.mine(sent[2], false) require.NotEmpty(t, ReconcileSubmitted(t.Context(), s, ca)) require.Equal(t, "confirmed", ticketPhase(t, s, b.Sig)) require.Equal(t, "reverted", ticketPhase(t, s, a.Sig)) + require.Equal(t, "retryable", ticketPhase(t, s, sibling.Sig)) + require.EqualValues(t, 2, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"})) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_settlements_total", nil)) + require.NoError(t, s.finishTicket(t.Context(), b.Sig, "confirmed", b0.Hash.Hex())) + require.EqualValues(t, 2, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "retryable"})) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_settlements_total", nil)) + require.NoError(t, s.setTicketPhase(t.Context(), sibling.Sig, "invalid")) next := nextRecoveryTicket(a, 105) require.NoError(t, s.storeWinningTickets(t.Context(), a.PayerAddress, next.RecipientRandHash, 0, big.NewInt(1000), []*pm.SignedTicket{next}), "B consumed nonce zero and A's nonce one failed; A has no remaining liability") } @@ -1084,3 +1122,59 @@ func TestFinalizedUsePollingRetainsOnlyUnresolvedWork(t *testing.T) { }) } } + +// Configure before sending work so the callback is immutable while jobs run. +func captureRecoveryResults(t *testing.T, s *RedeemerDB) func() *eth.TransactionReceipt { + t.Helper() + results := make(chan *eth.TransactionReceipt, 8) + completed := s.recovery.manager.Completed + s.recovery.manager.Completed = func(ctx context.Context, result *eth.TransactionReceipt) { completed(ctx, result); results <- result } + return func() *eth.TransactionReceipt { + t.Helper() + select { + case result := <-results: + return result + case <-time.After(3 * time.Second): + t.Fatal("redemption callback did not complete") + return nil + } + } +} + +func TestRedemptionCallbackObservations(t *testing.T) { + for _, failCommit := range []bool{false, true} { + t.Run(fmt.Sprintf("commit_failure=%t", failCommit), func(t *testing.T) { + f, s, ticket, c, key := newRecoveryTest(t, 112) + s.metrics = observability.New("orchestrator") + f.finalized = false + f.mineAfter = 1 + if failCommit { + _, err := s.db.Exec(`CREATE TRIGGER fail_mined BEFORE UPDATE OF phase ON redemption_attempts WHEN NEW.phase='mined' BEGIN SELECT RAISE(ABORT,'storage failure'); END`) + require.NoError(t, err) + } + require.NoError(t, StartRedemptionRecovery(t.Context(), s, c, key, RedemptionOptions{Timeout: time.Hour, MaxReplacements: 0})) + nextResult := captureRecoveryResults(t, s) + tickRecovery(t, s, c, key) + result := nextResult() + require.NoError(t, result.Error()) + if failCommit { + require.NotEqual(t, "mined", ticketPhase(t, s, ticket.Sig)) + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "mined"})) + _, err := s.db.Exec(`DROP TRIGGER fail_mined`) + require.NoError(t, err) + require.NoError(t, s.recovery.recordResult(t.Context(), result)) + } + require.Equal(t, "mined", ticketPhase(t, s, ticket.Sig)) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "mined"})) + require.NoError(t, s.recovery.recordResult(t.Context(), result)) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_transitions_total", map[string]string{"event": "mined"})) + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "redemption_settlements_total", nil)) + f.mu.Lock() + f.finalized = true + f.mu.Unlock() + require.Empty(t, ReconcileSubmitted(t.Context(), s, c)) + require.Empty(t, ReconcileSubmitted(t.Context(), s, c)) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "redemption_settlements_total", nil)) + }) + } +} diff --git a/orchestrator/redemption_store.go b/orchestrator/redemption_store.go index bc0a5d8..0207963 100644 --- a/orchestrator/redemption_store.go +++ b/orchestrator/redemption_store.go @@ -6,12 +6,14 @@ import ( "errors" "fmt" "math" + "math/big" "strconv" "time" ethcommon "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm" ) @@ -71,7 +73,15 @@ func (s *RedeemerDB) recordTransaction(ctx context.Context, sig []byte, prepared if err != nil { return err } - return tx.Commit() + if err := tx.Commit(); err != nil { + return err + } + event := "prepared" + if previous != "" { + event = "replacement_prepared" + } + s.observeTransition(event, prepared.Hash.Hex(), nil) + return nil } func nullString(s string) any { if s == "" { @@ -155,6 +165,11 @@ func broadcastSavedRedemption(ctx context.Context, store *RedeemerDB, contracts if err = tx.Commit(); err != nil { return err } + // An acknowledged replay does not begin a new logical broadcast phase. + broadcastChanged := !preserve && previousPhase != "sending" && previousPhase != "broadcast" && previousPhase != "submitted" + if broadcastChanged { + store.observeTransition("broadcast", identity.Hash.Hex(), nil) + } sendErr := contracts.Broadcast(ctx, identity) phase := "submitted" var message any @@ -178,14 +193,25 @@ func broadcastSavedRedemption(ctx context.Context, store *RedeemerDB, contracts return errors.Join(sendErr, err) } defer tx.Rollback() - _, err = tx.Exec(`UPDATE redemption_transactions SET phase=?,error=?,acknowledged=max(acknowledged,?) WHERE hash=? AND phase=?`, phase, message, ack, identity.Hash.Hex(), claimedPhase) + result, err = tx.Exec(`UPDATE redemption_transactions SET phase=?,error=?,acknowledged=max(acknowledged,?) WHERE hash=? AND phase=?`, phase, message, ack, identity.Hash.Hex(), claimedPhase) + var summaryResult sql.Result if err == nil { - _, err = tx.Exec(`UPDATE redemption_attempts SET phase=?,error=? WHERE sig=? AND phase='broadcast' AND EXISTS(SELECT 1 FROM winning_tickets WHERE sig=? AND tx_hash=?)`, phase, message, sig, sig, identity.Hash.Hex()) + summaryResult, err = tx.Exec(`UPDATE redemption_attempts SET phase=?,error=? WHERE sig=? AND phase='broadcast' AND EXISTS(SELECT 1 FROM winning_tickets WHERE sig=? AND tx_hash=?)`, phase, message, sig, sig, identity.Hash.Hex()) } if err != nil { return errors.Join(sendErr, err) } - return errors.Join(sendErr, tx.Commit()) + commitErr := tx.Commit() + if commitErr == nil { + store.metrics.Add("redemption_broadcasts_total", 1, observability.Labels{"outcome": observability.ErrorKind(sendErr)}) + changed, _ := result.RowsAffected() + summaryChanged, _ := summaryResult.RowsAffected() + if changed+summaryChanged > 0 && !preserve && (broadcastChanged || phase != previousPhase) { + // Broadcast errors are observed by the caller; this records the phase. + store.observeTransition(phase, identity.Hash.Hex(), nil) + } + } + return errors.Join(sendErr, commitErr) } func signedIdentity(tx *types.Transaction) (eth.SignedTransaction, error) { @@ -207,6 +233,23 @@ func (s *RedeemerDB) finishTicket(ctx context.Context, sig []byte, phase string, return err } defer tx.Rollback() + var retried []string + commit := func() error { + if err := tx.Commit(); err != nil { + return err + } + for _, hash := range retried { + s.observeTransition("retryable", hash, nil) + } + return nil + } + var oldPhase, enqueued string + var face []byte + var redeemed bool + var observationErr error + if s.metrics != nil { + observationErr = tx.QueryRowContext(ctx, `SELECT COALESCE(a.phase,''),COALESCE(w.enqueued_at,''),w.face_value,w.redeemed_at IS NOT NULL FROM winning_tickets w LEFT JOIN redemption_attempts a ON a.sig=w.sig WHERE w.sig=?`, sig).Scan(&oldPhase, &enqueued, &face, &redeemed) + } if hash == "" && phase != "used" { var latest sql.NullString if err := tx.QueryRowContext(ctx, "SELECT tx_hash FROM winning_tickets WHERE sig=?", sig).Scan(&latest); err != nil { @@ -220,7 +263,21 @@ func (s *RedeemerDB) finishTicket(ctx context.Context, sig []byte, phase string, // applying the ticket outcome, which may already be a finalized success. _, err = tx.ExecContext(ctx, `UPDATE redemption_transactions SET phase='superseded',error=NULL WHERE hash!=? AND (redeemer_address,nonce)=(SELECT redeemer_address,nonce FROM redemption_transactions WHERE hash=?) AND phase NOT IN ('confirmed','reverted')`, hash, hash) if err == nil { - _, err = tx.ExecContext(ctx, `UPDATE redemption_attempts SET phase='retryable',error=NULL WHERE sig!=? AND phase IN ('prepared','broadcast','submitted','mined') AND EXISTS(SELECT 1 FROM winning_tickets w JOIN redemption_transactions t ON t.hash=w.tx_hash WHERE w.sig=redemption_attempts.sig AND t.phase='superseded' AND (t.redeemer_address,t.nonce)=(SELECT redeemer_address,nonce FROM redemption_transactions WHERE hash=?))`, sig, hash) + var rows *sql.Rows + rows, err = tx.QueryContext(ctx, `UPDATE redemption_attempts SET phase='retryable',error=NULL WHERE sig!=? AND phase IN ('prepared','broadcast','submitted','mined') AND EXISTS(SELECT 1 FROM winning_tickets w JOIN redemption_transactions t ON t.hash=w.tx_hash WHERE w.sig=redemption_attempts.sig AND t.phase='superseded' AND (t.redeemer_address,t.nonce)=(SELECT redeemer_address,nonce FROM redemption_transactions WHERE hash=?)) RETURNING (SELECT tx_hash FROM winning_tickets WHERE sig=redemption_attempts.sig)`, sig, hash) + if err == nil { + for rows.Next() { + var sibling sql.NullString + if err = rows.Scan(&sibling); err != nil { + break + } + retried = append(retried, sibling.String) + } + if err == nil { + err = rows.Err() + } + rows.Close() + } } var message any if phase == "reverted" { @@ -241,7 +298,7 @@ func (s *RedeemerDB) finishTicket(ctx context.Context, sig []byte, phase string, if n, err := result.RowsAffected(); err != nil { return err } else if n == 0 { - return tx.Commit() + return commit() } if phase == "confirmed" || phase == "used" { _, err = tx.ExecContext(ctx, `UPDATE winning_tickets SET redeemed_at=COALESCE(redeemed_at,?),tx_hash=COALESCE(?,tx_hash) WHERE sig=?`, time.Now().UTC().Format(time.RFC3339Nano), nullString(hash), sig) @@ -256,5 +313,20 @@ func (s *RedeemerDB) finishTicket(ctx context.Context, sig []byte, phase string, if err != nil { return err } - return tx.Commit() + if err := commit(); err != nil { + return err + } + if s.metrics != nil && observationErr == nil { + if oldPhase != phase { + s.observeTransition(phase, hash, nil) + } + if !redeemed && (phase == "confirmed" || phase == "used") { + s.metrics.Add("redemption_settlements_total", 1, nil) + s.metrics.Add("redemption_settled_eth_total", observability.ETH(new(big.Rat).SetInt(new(big.Int).SetBytes(face))), nil) + if at, err := time.Parse(time.RFC3339Nano, enqueued); err == nil { + s.metrics.Observe("redemption_settlement_duration_seconds", max(time.Since(at).Seconds(), 0), nil) + } + } + } + return nil } diff --git a/orchestrator/registry.go b/orchestrator/registry.go index 1b6ef63..4db2921 100644 --- a/orchestrator/registry.go +++ b/orchestrator/registry.go @@ -8,6 +8,7 @@ import ( "encoding/json" "errors" "fmt" + "log/slog" "maps" "math/big" "net/http" @@ -19,6 +20,7 @@ import ( "github.com/livepeer/node/destination" discovery "github.com/livepeer/node/discovery/shared" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm" ) @@ -105,6 +107,7 @@ type runner struct { } type session struct { + identity observability.Identity pending bool ID string Token string @@ -116,6 +119,16 @@ type session struct { } var errInvalidSessionToken = errors.New("invalid session token") +var errRunnerUnavailable = errors.New("runner unavailable") + +var ( + errRunnerCapacity = errors.New("runner at capacity") + errSessionCapacity = errors.New("session capacity reached") +) + +func capacityError(err error) bool { + return errors.Is(err, errRunnerCapacity) || errors.Is(err, errSessionCapacity) +} // runnerStopped bounds the time existing proxy requests have to finish. type runnerStopped struct{ deadline time.Time } @@ -128,6 +141,9 @@ type sessionProxy struct { } type Registry struct { + logger *slog.Logger + metrics *observability.Metrics + server *Server mu sync.Mutex runners map[string]*runner secret string @@ -145,7 +161,14 @@ type Registry struct { const maxRunners = 256 func NewRegistry(secret, service string, interval, ttl time.Duration) *Registry { - return &Registry{runners: make(map[string]*runner), secret: secret, service: strings.TrimRight(service, "/"), interval: interval, ttl: ttl} + r := &Registry{metrics: observability.New("orchestrator"), runners: make(map[string]*runner), secret: secret, service: strings.TrimRight(service, "/"), interval: interval, ttl: ttl} + r.metrics.Snapshot(r.collectMetrics) + r.metrics.Legacy(func(emit observability.Emit) { + runners, sessions := r.Counts() + emit("runners", float64(runners), nil) + emit("sessions", float64(sessions), nil) + }) + return r } func (r *Registry) runnerServiceURL() string { @@ -165,6 +188,7 @@ func (r *Registry) setRate(rate *big.Rat, until time.Time) { defer r.mu.Unlock() r.weiPerUSD = new(big.Rat).Set(rate) r.rateUntil = until + r.metrics.Gauge("price_feed_valid_until_timestamp_seconds", nil).Set(float64(until.Unix()) * observability.Bool(!until.IsZero())) for _, item := range r.runners { quote := item.USDQuote item.PriceError = normalizePriceAt("e, r.weiPerUSD) != nil @@ -359,6 +383,7 @@ func (r *Registry) Heartbeat(req heartbeatRequest, auth string) (heartbeatRespon resp := heartbeatResponse{RunnerID: req.RunnerID, Orchestrator: r.runnerServiceURL(), HeartbeatInterval: r.interval.String(), HeartbeatTTL: r.ttl.String(), SessionIDs: ids} if initial { resp.HeartbeatSecret = current.Credential + r.runnerEvent(req.RunnerID, current, "registered") } return resp, http.StatusOK, nil } @@ -374,11 +399,12 @@ func (r *Registry) Unregister(id, auth string) (int, error) { return http.StatusUnauthorized, errors.New("invalid runner credential") } for sid := range current.Sessions { - r.releaseLocked(id, sid, nil) + r.releaseLocked(id, sid, nil, "runner_unregistered") } if r.onEvent != nil { r.onEvent(id, "unregistered", "", "") } + r.runnerEvent(id, current, "unregistered") delete(r.runners, id) return http.StatusOK, nil } @@ -441,10 +467,24 @@ func (r *Registry) ReserveWithID(id, requestedID string) (string, string, string return r.reserveWithPrice(id, requestedID, nil) } -func (r *Registry) reserveWithPrice(id, requestedID string, agreed *priceInfo) (string, string, string, int, error) { +func (r *Registry) reserveWithPrice(id, requestedID string, agreed *priceInfo) (sid, app, control string, status int, result error) { r.mu.Lock() defer r.mu.Unlock() item := r.runners[id] + if item != nil { + defer func() { + outcome := "success" + if result != nil { + outcome = "rejected" + if capacityError(result) { + outcome = "capacity" + } else if status == 503 { + outcome = "unavailable" + } + } + r.metrics.Add("session_reservations_total", 1, runnerIdentity(id, item).Labels().With("outcome", outcome)) + }() + } if item == nil || !r.usable(item) { return "", "", "", http.StatusNotFound, errors.New("runner unavailable") } @@ -459,10 +499,10 @@ func (r *Registry) reserveWithPrice(id, requestedID string, agreed *priceInfo) ( total += len(registered.Sessions) } if total >= 10000 { - return "", "", "", http.StatusServiceUnavailable, errors.New("session capacity reached") + return "", "", "", http.StatusServiceUnavailable, errSessionCapacity } if len(item.Sessions) >= item.Capacity { - return "", "", "", http.StatusServiceUnavailable, errors.New("runner at capacity") + return "", "", "", http.StatusServiceUnavailable, errRunnerCapacity } sessionID := requestedID if sessionID == "" { @@ -484,7 +524,7 @@ func (r *Registry) reserveWithPrice(id, requestedID string, agreed *priceInfo) ( price = *agreed } ctx, cancel := context.WithCancelCause(context.Background()) - item.Sessions[sessionID] = &session{pending: agreed != nil, ID: sessionID, Token: token, Created: time.Now(), Proxies: map[string]sessionProxy{}, PriceInfo: price, ctx: ctx, cancel: cancel} + item.Sessions[sessionID] = &session{identity: runnerIdentity(id, item), pending: agreed != nil, ID: sessionID, Token: token, Created: time.Now(), Proxies: map[string]sessionProxy{}, PriceInfo: price, ctx: ctx, cancel: cancel} appURL := r.appURL(id, item.Mode, sessionID) if item.Proxy && item.Mode == "persistent" { target, _ := url.Parse(item.RunnerURL) @@ -550,12 +590,12 @@ func (r *Registry) PaidSessions() []string { return ids } -func (r *Registry) ReleaseBySession(sid string) { +func (r *Registry) ReleaseBySession(sid string, reasons ...string) { r.mu.Lock() defer r.mu.Unlock() for id, item := range r.runners { if item.Sessions[sid] != nil { - r.releaseLocked(id, sid, nil) + r.releaseLocked(id, sid, nil, reasons...) return } } @@ -572,21 +612,37 @@ func (r *Registry) release(id, sid, token string, callback bool) (int, error) { return http.StatusUnauthorized, errInvalidSessionToken } var cause error + reason := "client_stop" if callback { - cause = runnerStopped{deadline: time.Now().Add(time.Second)} + cause, reason = runnerStopped{deadline: time.Now().Add(time.Second)}, "runner_stop" } - r.releaseLocked(id, sid, cause) + r.releaseLocked(id, sid, cause, reason) return http.StatusOK, nil } // releaseLocked is the single teardown path for capacity and active requests. // The caller holds r.mu; cancellation never waits for the request to finish. -func (r *Registry) releaseLocked(id, sid string, cause error) { +func (r *Registry) releaseLocked(id, sid string, cause error, reasons ...string) { item := r.runners[id] if item == nil || item.Sessions[sid] == nil { return } - item.Sessions[sid].cancel(cause) + sess := item.Sessions[sid] + reason := "released" + if len(reasons) != 0 { + reason = reasons[0] + } + if sess.pending && (reason == "released" || reason == "completed") { + reason = "reservation_failed" + } + r.metrics.Add("session_ends_total", 1, sess.identity.Labels().With("reason", reason)) + if !sess.pending { + r.metrics.Observe("session_duration_seconds", time.Since(sess.Created).Seconds(), sess.identity.Labels()) + } + if r.logger != nil { + r.logger.Info("session ended", "event", "session_ended", "operation", "release", "outcome", reason, "app", sess.identity.App, "runner_id", id, "session_id", sid) + } + sess.cancel(cause) delete(item.Sessions, sid) if r.onEvent != nil { r.onEvent(id, "released", sid, "") @@ -609,7 +665,7 @@ func (r *Registry) Close() { r.closed = true for id, item := range r.runners { for sid := range item.Sessions { - r.releaseLocked(id, sid, nil) + r.releaseLocked(id, sid, nil, "shutdown") } if r.onEvent != nil { r.onEvent(id, "unregistered", "", "") @@ -681,11 +737,12 @@ func (r *Registry) Expire() { for id, item := range r.runners { if !item.Static && time.Since(item.Last) > r.ttl { for sid := range item.Sessions { - r.releaseLocked(id, sid, nil) + r.releaseLocked(id, sid, errRunnerUnavailable, "runner_expired") } if r.onEvent != nil { r.onEvent(id, "expired", "", "") } + r.runnerEvent(id, item, "expired") delete(r.runners, id) } } @@ -745,6 +802,7 @@ func (r *Registry) AddStatic(config StaticRunner) error { return errors.New("static runner capacity reached") } r.runners[config.ID] = &runner{USDQuote: quote, heartbeatRequest: req, Static: true, Healthy: config.HealthURL == "", HealthURL: config.HealthURL, HealthCode: config.HealthCode, Sessions: map[string]*session{}} + r.runnerEvent(config.ID, r.runners[config.ID], "registered") return nil } @@ -792,16 +850,24 @@ func (r *Registry) checkStaticHealth(ctx context.Context, client *http.Client, i } r.mu.Lock() if item := r.runners[id]; item != nil && item.Static { + r.metrics.Add("runner_health_checks_total", 1, runnerIdentity(id, item).Labels().With("outcome", map[bool]string{true: "success", false: "error"}[healthy])) if healthy { item.healthFailures = 0 } else { item.healthFailures++ healthy = item.Healthy && item.healthFailures < 3 } + if item.Healthy != healthy { + event := "unhealthy" + if healthy { + event = "healthy" + } + r.runnerEvent(id, item, event) + } item.Healthy = healthy if !healthy { for sid := range item.Sessions { - r.releaseLocked(id, sid, nil) + r.releaseLocked(id, sid, errRunnerUnavailable, "runner_unhealthy") } } } diff --git a/orchestrator/trickle.go b/orchestrator/trickle.go index 1f1a3bc..0e41f02 100644 --- a/orchestrator/trickle.go +++ b/orchestrator/trickle.go @@ -6,6 +6,7 @@ import ( "net/http" "time" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/trickle" ) @@ -14,6 +15,7 @@ const o2rKeepaliveMessage = `{"keep":"alive"}` // channel tracks ownership; trickle.Server owns the stream and its segments. type channel struct { name, mime, runnerID, sessionID string + identity observability.Identity publisher *trickle.TrickleLocalPublisher } diff --git a/orchestrator/trickle_test.go b/orchestrator/trickle_test.go index 78693d7..44d2d6c 100644 --- a/orchestrator/trickle_test.go +++ b/orchestrator/trickle_test.go @@ -11,6 +11,7 @@ import ( "testing/synctest" "time" + "github.com/livepeer/node/internal/test" "github.com/stretchr/testify/require" ) @@ -55,7 +56,7 @@ func TestTrickleActiveStreamAndCancellation(t *testing.T) { require.NoError(t, reg.AddStatic(StaticRunner{ID: "r", RunnerURL: "http://127.0.0.1:1", App: "test"})) sid, _, _, _, err := reg.Reserve("r") require.NoError(t, err) - s.newChannel("test", "events", "application/octet-stream", "r", sid) + s.newChannel("test", "events", "application/octet-stream", "r", sid).identity = reg.identity("r", sid) input, writer := io.Pipe() defer writer.Close() pubDone, subDone := make(chan struct{}), make(chan struct{}) @@ -104,11 +105,62 @@ func TestTrickleActiveStreamAndCancellation(t *testing.T) { default: t.Error("subscriber was not interrupted") } + require.GreaterOrEqual(t, test.MetricSum(t, reg.metrics.Registry, "stream_transfer_bytes_total", map[string]string{"app": "test", "runner_id": "r", "protocol": "trickle", "direction": "out"}), float64(len("firststill streaming"))) + require.Zero(t, test.MetricSum(t, reg.metrics.Registry, "http_requests_in_flight", nil)) }) }) } } +func TestTrickleOwnershipSurvivesHeartbeatChanges(t *testing.T) { + upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { _, _ = io.WriteString(w, "proxy reply") })) + defer upstream.Close() + reg, s := reviewServer(t, upstream.URL) + defer s.Close() + request := httptest.NewRequest("POST", "/runners/heartbeat", strings.NewReader(`{"runner_id":"r","runner_url":"http://127.0.0.1:1","app":"original","capacity":1}`)) + request.Header.Set("Authorization", "bootstrap") + response := httptest.NewRecorder() + s.ServeHTTP(response, request) + require.Equal(t, http.StatusOK, response.Code, response.Body.String()) + var registered heartbeatResponse + require.NoError(t, json.Unmarshal(response.Body.Bytes(), ®istered)) + require.NotNil(t, registered.O2R) + require.Len(t, test.MetricSamples(t, reg.metrics.Registry, "runner_sessions", map[string]string{"runner_id": "r", "state": "active"}), 1) + require.Zero(t, test.MetricSum(t, reg.metrics.Registry, "runner_sessions", map[string]string{"runner_id": "r"})) + s.mu.Lock() + s.publishSessionEvent(registered.O2R.ChannelName, []byte("ownership")) + s.mu.Unlock() + _, _, err := reg.Heartbeat(heartbeatRequest{RunnerID: "r", RunnerURL: "http://127.0.0.1:1", App: "updated", Capacity: 1}, registered.HeartbeatSecret) + require.NoError(t, err) + response = httptest.NewRecorder() + s.ServeHTTP(response, httptest.NewRequest("GET", registered.O2R.URL+"/0", nil)) + require.Equal(t, http.StatusOK, response.Code, response.Body.String()) + require.Equal(t, "ownership", response.Body.String()) + require.EqualValues(t, len("ownership"), test.MetricSum(t, reg.metrics.Registry, "stream_transfer_bytes_total", map[string]string{"app": "original", "direction": "out"})) + require.Zero(t, test.MetricSum(t, reg.metrics.Registry, "stream_transfer_bytes_total", map[string]string{"app": "updated"})) + reg.proxyTemplate = "https://{proxy}.apps.example" + require.NoError(t, reg.AddStatic(StaticRunner{ID: "proxy", App: "generated", Mode: "single-shot", RunnerURL: upstream.URL, Capacity: 1, Proxy: true})) + response = httptest.NewRecorder() + s.ServeHTTP(response, httptest.NewRequest("GET", "https://proxy.apps.example/ai/trickle/"+registered.O2R.ChannelName+"/0", nil)) + require.Equal(t, 200, response.Code, response.Body.String()) + require.Equal(t, "proxy reply", response.Body.String()) + require.EqualValues(t, 1, test.MetricSum(t, reg.metrics.Registry, "app_calls_total", map[string]string{"app": "generated", "protocol": "http"})) + for _, app := range []string{"generated", "original"} { + require.Zero(t, test.MetricSum(t, reg.metrics.Registry, "app_calls_in_flight", map[string]string{"app": app})) + } + _, err = reg.Unregister("r", registered.HeartbeatSecret) + for _, name := range []string{"runner_registered", "runner_sessions", "runner_capacity_available"} { + require.Empty(t, test.MetricSamples(t, reg.metrics.Registry, name, map[string]string{"runner_id": "r"})) + } + require.NoError(t, err) + before := test.MetricSum(t, reg.metrics.Registry, "stream_transfer_bytes_total", nil) + response = httptest.NewRecorder() + s.ServeHTTP(response, httptest.NewRequest("GET", registered.O2R.URL+"/0", nil)) + require.Equal(t, http.StatusNotFound, response.Code) + require.Equal(t, before, test.MetricSum(t, reg.metrics.Registry, "stream_transfer_bytes_total", nil), "removed ownership must not create empty-label transfer measurements") + +} + func TestNamedChannelsAreIdempotentAndReleased(t *testing.T) { reg, s := reviewServer(t, "http://127.0.0.1:1") require.NoError(t, reg.AddStatic(StaticRunner{ID: "r", RunnerURL: "http://127.0.0.1:1", App: "test"})) diff --git a/signer/app.go b/signer/app.go index 1a865ee..6f9edc1 100644 --- a/signer/app.go +++ b/signer/app.go @@ -5,7 +5,6 @@ import ( "errors" "fmt" "io" - "log/slog" "math/big" "net" "net/http" @@ -172,6 +171,7 @@ func serve(parent context.Context, p Params) error { return fmt.Errorf("configure signer RPC (LIVEPEER_SIGNER_RPC_URL or --rpc-url-file): %w", err) } defer rpc.Close() + rpc.SetObserver(service.metrics.RPC) var chainID *big.Int if p.ChainID != nil { chainID = new(big.Int).SetUint64(*p.ChainID) @@ -185,13 +185,11 @@ func serve(parent context.Context, p Params) error { } service.SetPaymentChain(pm.EthereumChain{Client: eth.PaymentChain{Contracts: contracts}}) policy, _ := newPricePolicy(p.MaxHourlyPrice, p.MaxFixedPrice) + policy.metrics = service.metrics if p.WeiPerUSD == nil { - rate, until, err := contracts.WeiPerUSD(ctx, p.ETHUSDFeed, p.ETHUSDMaxAge) - if err != nil { - slog.Error("signer price feed unavailable at startup; check --eth-usd-feed, --eth-usd-max-age and LIVEPEER_SIGNER_RPC_URL or --rpc-url-file", "error", err) - } else if err := policy.setRate(rate, until); err != nil { - slog.Error("signer price feed invalid at startup; check --eth-usd-feed and --eth-usd-max-age", "error", err) - } + _ = policy.refreshFeed(ctx, func(ctx context.Context) (*big.Rat, time.Time, error) { + return contracts.WeiPerUSD(ctx, p.ETHUSDFeed, p.ETHUSDMaxAge) + }) } else if err := policy.setRate(p.WeiPerUSD, time.Time{}); err != nil { return err } @@ -218,6 +216,7 @@ func serve(parent context.Context, p Params) error { } defer func() { _ = producer.Close() }() if producer != nil { + service.metrics.Legacy(producer.collectMetrics) service.events = producer } listener, err := net.Listen("tcp", p.Listen.String()) @@ -239,6 +238,9 @@ func serve(parent context.Context, p Params) error { ctx, cancel := context.WithTimeout(r.Context(), 5*time.Second) defer cancel() funds, err := service.paymentChain.PayerFunds(ctx, key.Address(), ethcommon.Address{}) + if err == nil { + service.observeFunds(funds, true) + } if err != nil || pm.ValidatePayerFunds(funds) != nil || !service.pricePolicy.ready() || !producer.ready(ctx) { http.Error(w, "signer payment dependencies unavailable", http.StatusServiceUnavailable) return @@ -246,11 +248,7 @@ func serve(parent context.Context, p Params) error { w.WriteHeader(http.StatusOK) _, _ = io.WriteString(w, "ready\n") }) - metricsMux.HandleFunc("GET /metrics", func(w http.ResponseWriter, r *http.Request) { - w.Header().Set("Content-Type", "text/plain; version=0.0.4") - _, _ = io.WriteString(w, "livepeer_signer_up 1\n") - producer.metrics(r.Context(), w) - }) + metricsMux.Handle("GET /metrics", service.metrics.Handler()) srv := &http.Server{BaseContext: func(net.Listener) context.Context { return ctx }, Handler: service, ReadHeaderTimeout: 5 * time.Second, IdleTimeout: 30 * time.Second, MaxHeaderBytes: 16 << 10, MaxHeaderValueCount: 128} metricsServer := &http.Server{BaseContext: srv.BaseContext, Handler: metricsMux, ReadHeaderTimeout: 5 * time.Second, WriteTimeout: 10 * time.Second, IdleTimeout: 30 * time.Second, MaxHeaderBytes: 16 << 10, MaxHeaderValueCount: 128} errCh := make(chan error, 2) diff --git a/signer/auth.go b/signer/auth.go index 4f719db..e67aa2e 100644 --- a/signer/auth.go +++ b/signer/auth.go @@ -11,9 +11,11 @@ import ( "log/slog" "net/http" "net/url" + "strconv" "time" "github.com/livepeer/node/destination" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm/wire" ) @@ -54,19 +56,30 @@ func (s *Service) SetAuthWebhook(endpoint *url.URL, headers Headers) error { } func (s *Service) authorizePayment(r *http.Request, req paymentRequest, price wire.PriceInfo, state *paymentState) error { + logger := slog.With("component", "signer", "event", "authorization", "operation", "authorization") identity := r.Header.Get("Signer-Auth-Id") - if s.authURL != nil && (state.AuthPolicy != s.authPolicy || state.AuthExpiry == 0 || time.Now().Unix() > state.AuthExpiry) { + refresh := s.authURL != nil && (state.AuthPolicy != s.authPolicy || state.AuthExpiry == 0 || time.Now().Unix() > state.AuthExpiry) + if s.authURL != nil && !refresh { + s.metrics.Add("signer_auth_cache_hits_total", 1, nil) + } + if refresh { + started := time.Now() + status, outcome := 0, "error" + defer func() { + s.metrics.Add("signer_auth_webhook_requests_total", 1, observability.Labels{"status": strconv.Itoa(status), "outcome": outcome}) + s.metrics.Observe("signer_auth_webhook_duration_seconds", time.Since(started).Seconds(), nil) + }() body, err := json.Marshal(struct { Headers http.Header `json:"headers"` State *paymentState `json:"state"` }{r.Header, state}) if err != nil { - slog.ErrorContext(r.Context(), "signer auth payload encoding failed", "error", err) + logger.ErrorContext(r.Context(), "signer auth payload encoding failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) return err } request, err := http.NewRequestWithContext(r.Context(), http.MethodPost, s.authURL.String(), bytes.NewReader(body)) if err != nil { - slog.ErrorContext(r.Context(), "signer auth request construction failed", "error", err) + logger.ErrorContext(r.Context(), "signer auth request construction failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) return err } request.Header.Set("Content-Type", "application/json") @@ -78,22 +91,23 @@ func (s *Service) authorizePayment(r *http.Request, req paymentRequest, price wi } response, err := s.authClient.Do(request) if err != nil { - slog.ErrorContext(r.Context(), "signer auth webhook unavailable", "error", err) - return paymentFailure{502, "signer auth webhook unavailable"} + logger.ErrorContext(r.Context(), "signer auth webhook unavailable", "outcome", "error", "error_kind", observability.ErrorKind(err)) + return serviceFailure(502, "signer auth webhook unavailable") } defer response.Body.Close() + status = response.StatusCode if response.StatusCode != 200 { - slog.ErrorContext(r.Context(), "signer auth webhook returned non-200 HTTP status", "http_status", response.StatusCode) - return paymentFailure{502, "signer auth webhook failed"} + logger.ErrorContext(r.Context(), "signer auth webhook returned non-200 HTTP status", "outcome", "error", "error_kind", "http_status", "http_status", response.StatusCode) + return serviceFailure(502, "signer auth webhook failed") } data, err := io.ReadAll(io.LimitReader(response.Body, (1<<20)+1)) if err != nil { - slog.ErrorContext(r.Context(), "signer auth response read failed", "error", err) - return paymentFailure{502, "invalid signer auth response"} + logger.ErrorContext(r.Context(), "signer auth response read failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) + return serviceFailure(502, "invalid signer auth response") } if len(data) > 1<<20 { - slog.ErrorContext(r.Context(), "signer auth response exceeds size limit") - return paymentFailure{502, "invalid signer auth response"} + logger.ErrorContext(r.Context(), "signer auth response exceeds size limit", "outcome", "error", "error_kind", "response_limit") + return serviceFailure(502, "invalid signer auth response") } var auth struct { Status int `json:"status"` @@ -103,16 +117,17 @@ func (s *Service) authorizePayment(r *http.Request, req paymentRequest, price wi MaxPrice *maxPrice `json:"maxPrice"` } if err := json.Unmarshal(data, &auth); err != nil { - slog.ErrorContext(r.Context(), "signer auth response decoding failed", "error", err) - return paymentFailure{502, "invalid signer auth response"} + logger.ErrorContext(r.Context(), "signer auth response decoding failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) + return serviceFailure(502, "invalid signer auth response") } if auth.Status != 200 && (auth.Status < 400 || auth.Status > 599) { - slog.ErrorContext(r.Context(), "signer auth response has invalid decision status", "decision_status", auth.Status) - return paymentFailure{502, "invalid signer auth response"} + logger.ErrorContext(r.Context(), "signer auth response has invalid decision status", "outcome", "error", "error_kind", "invalid_decision", "decision_status", auth.Status) + return serviceFailure(502, "invalid signer auth response") } if auth.Status != 200 { - slog.WarnContext(r.Context(), "signer authorization rejected", "decision_status", auth.Status) - return paymentFailure{auth.Status, fmt.Sprintf("signer auth rejected request with status %d", auth.Status)} + outcome = "denied" + logger.WarnContext(r.Context(), "signer authorization rejected", "outcome", "denied", "error_kind", "policy_rejected", "decision_status", auth.Status) + return errors.Join(paymentFailure{auth.Status, fmt.Sprintf("signer auth rejected request with status %d", auth.Status)}, errAuthorizationDenied) } if auth.AuthID != "" { identity = auth.AuthID @@ -120,19 +135,22 @@ func (s *Service) authorizePayment(r *http.Request, req paymentRequest, price wi state.AuthExpiry, state.AuthPolicy, state.AuthMaxPrice = auth.Expiry, s.authPolicy, "" if auth.MaxPrice != nil { if err := checkMaxPrice(paymentRequest{Type: req.Type, MaxPrice: auth.MaxPrice}, price); err != nil { - slog.WarnContext(r.Context(), "signer auth price ceiling rejected", "error", err) if f, ok := errors.AsType[paymentFailure](err); ok && f.status == http.StatusBadRequest { - return paymentFailure{http.StatusBadGateway, "signer auth invalid maxPrice"} + logger.ErrorContext(r.Context(), "signer auth invalid maxPrice", "outcome", "error", "error_kind", "invalid_policy") + return serviceFailure(http.StatusBadGateway, "signer auth invalid maxPrice") } - return err + outcome = "denied" + logger.WarnContext(r.Context(), "signer auth price ceiling rejected", "outcome", outcome, "error_kind", "price_ceiling") + return errors.Join(err, errAuthorizationDenied) } state.AuthMaxPrice = auth.MaxPrice.Price.String() } + outcome = "success" } // Apply webhook identity precedence before checking for an established ID change. if identity != "" && state.AuthID != identity { if state.AuthID != "" { - slog.WarnContext(r.Context(), "signer authorization identity changed") + logger.WarnContext(r.Context(), "signer authorization identity changed", "outcome", "denied", "error_kind", "identity_changed") return paymentFailure{403, "signer auth ID changed"} } state.AuthID = identity diff --git a/signer/auth_test.go b/signer/auth_test.go index 4d2f9cf..a1e63f2 100644 --- a/signer/auth_test.go +++ b/signer/auth_test.go @@ -14,6 +14,7 @@ import ( "time" ethcommon "github.com/ethereum/go-ethereum/common" + testhelpers "github.com/livepeer/node/internal/test" "github.com/livepeer/node/pm" "github.com/livepeer/node/pm/wire" "github.com/stretchr/testify/require" @@ -142,20 +143,44 @@ func TestAuthWebhookFailuresWithholdPayment(t *testing.T) { logs.Reset() before := calls.Load() require.NoError(t, s.SetAuthWebhook(testURL(t, webhook.URL+path), nil)) + outcome := "error" + switch path { + case "/price-limit", "/insufficient", "/denied", "/private-reason", "/private-failure": + outcome = "rejected" + } + beforeOutcome := testhelpers.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": outcome}) + webhookOutcome := "error" + if outcome == "rejected" { + webhookOutcome = "denied" + } + beforeWebhook := testhelpers.MetricSum(t, s.metrics.Registry, "signer_auth_webhook_requests_total", map[string]string{"outcome": webhookOutcome}) response := postPayment(t, s, request) requirePaymentFailure(t, response, test.want) + require.Equal(t, beforeOutcome+1, testhelpers.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": outcome})) + require.Equal(t, beforeWebhook+1, testhelpers.MetricSum(t, s.metrics.Registry, "signer_auth_webhook_requests_total", map[string]string{"outcome": webhookOutcome})) require.Zero(t, countingKey.calls.Load(), "failed authorization must not sign tickets, segment credentials, or state") require.NotContains(t, response.Body.String(), "private-webhook-detail") require.NotEmpty(t, logs.String()) + for _, line := range strings.Split(strings.TrimSpace(logs.String()), "\n") { + var fields map[string]any + require.NoError(t, json.Unmarshal([]byte(line), &fields)) + for _, key := range []string{"component", "event", "operation", "outcome"} { + require.NotEmpty(t, fields[key], key) + } + } require.NotContains(t, logs.String(), "private-webhook-detail") if path == "/http-error" || path == "/redirect" { require.Contains(t, logs.String(), `"http_status":`+strconv.Itoa(test.status)) } if path == "/malformed" { - require.Contains(t, logs.String(), "invalid character") + require.Contains(t, logs.String(), "invalid_json") } if path == "/invalid-reason" { - require.Contains(t, logs.String(), "cannot unmarshal number") + require.Contains(t, logs.String(), "invalid_json_type") + } + if path == "/price-limit" { + require.Contains(t, logs.String(), `"outcome":"denied"`) + require.NotContains(t, logs.String(), `"outcome":"error"`) } if strings.HasPrefix(path, "/private-") || path == "/denied" { require.Contains(t, response.Body.String(), "signer auth rejected request with status "+strconv.Itoa(test.want)) @@ -173,6 +198,9 @@ func TestAuthWebhookFailuresWithholdPayment(t *testing.T) { require.Zero(t, countingKey.calls.Load()) require.NotContains(t, response.Body.String(), "private-webhook-detail") require.Contains(t, logs.String(), "signer auth webhook unavailable") - require.Contains(t, logs.String(), "private-webhook-detail") - require.Contains(t, logs.String(), "connection refused") + require.NotContains(t, logs.String(), "private-webhook-detail") + require.Contains(t, logs.String(), "connection_refused") + require.Zero(t, testhelpers.MetricSum(t, s.metrics.Registry, "signer_sign_operations_total", nil)) + require.Zero(t, testhelpers.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": "success"})) + require.EqualValues(t, len(tests)+1, testhelpers.MetricSum(t, s.metrics.Registry, "signer_auth_webhook_requests_total", nil)) } diff --git a/signer/discovery_webhook.go b/signer/discovery_webhook.go index 9a645fe..d2314e1 100644 --- a/signer/discovery_webhook.go +++ b/signer/discovery_webhook.go @@ -14,6 +14,7 @@ import ( "time" discovery "github.com/livepeer/node/discovery/shared" + "github.com/livepeer/node/internal/observability" ) type orchestratorWebhook struct { @@ -110,7 +111,7 @@ func (h *orchestratorWebhook) refresh(ctx context.Context, transport http.RoundT } } else if ctx.Err() == nil { // fetch never returns a URL, credentials, or response body in errors. - slog.WarnContext(ctx, "signer orchestrator webhook refresh failed; retaining cached list", "error", err) + slog.With("component", "signer", "event", "orchestrator_webhook", "operation", "orchestrator_webhook").WarnContext(ctx, "signer orchestrator webhook refresh failed; retaining cached list", "outcome", "error", "error_kind", observability.ErrorKind(err)) } h.mu.Lock() close(h.refreshing) diff --git a/signer/kafka.go b/signer/kafka.go index f0aa464..d9d5b96 100644 --- a/signer/kafka.go +++ b/signer/kafka.go @@ -5,7 +5,6 @@ import ( "crypto/tls" "errors" "fmt" - "io" "log/slog" "net" "net/url" @@ -14,6 +13,7 @@ import ( "sync/atomic" "time" + "github.com/livepeer/node/internal/observability" "github.com/segmentio/kafka-go" "github.com/segmentio/kafka-go/sasl/plain" "github.com/segmentio/kafka-go/sasl/scram" @@ -139,6 +139,8 @@ type kafkaProducer struct { enqueueFailures atomic.Uint64 publishFailures atomic.Uint64 storageFailures atomic.Uint64 + deliveredEvents atomic.Uint64 + lastDelivery atomic.Int64 } func (c KafkaConfig) transport() (*kafka.Transport, error) { @@ -240,6 +242,8 @@ func (p *kafkaProducer) publish(ctx context.Context) (bool, error) { p.storageFailures.Add(1) return false, err } + p.deliveredEvents.Add(uint64(len(events))) + p.lastDelivery.Store(time.Now().Unix()) return true, nil } @@ -257,7 +261,7 @@ func (p *kafkaProducer) run(ctx context.Context) { if ctx.Err() != nil { return } - slog.WarnContext(ctx, "signer Kafka delivery failed; accounting events retained", "retry_after", backoff, "error", err) + slog.With("component", "signer", "event", "accounting_delivery", "operation", "accounting_delivery").WarnContext(ctx, "signer Kafka delivery failed; accounting events retained", "retry_after", backoff, "outcome", "error", "error_kind", observability.ErrorKind(err)) delay, wake = backoff, nil backoff = min(backoff*2, 30*time.Second) } @@ -273,25 +277,28 @@ func (p *kafkaProducer) ready(ctx context.Context) bool { return p == nil || p.outbox.ready(ctx) } -func (p *kafkaProducer) metrics(ctx context.Context, w io.Writer) { +func (p *kafkaProducer) collectMetrics(emit observability.Emit) { if p == nil { return } + ctx, cancel := context.WithTimeout(context.Background(), time.Second) + defer cancel() stats, err := p.outbox.stats(ctx) - if err != nil { - _, _ = io.WriteString(w, "livepeer_signer_kafka_outbox_healthy 0\n") - } else { + emit("signer_kafka_outbox_healthy", observability.Bool(err == nil && !p.outbox.unhealthy.Load()), nil) + if err == nil { age := 0.0 if !stats.Oldest.IsZero() { age = max(time.Since(stats.Oldest).Seconds(), 0) } - healthy := 1 - if p.outbox.unhealthy.Load() { - healthy = 0 - } - _, _ = fmt.Fprintf(w, "livepeer_signer_kafka_outbox_healthy %d\nlivepeer_signer_kafka_pending_events %d\nlivepeer_signer_kafka_pending_bytes %d\nlivepeer_signer_kafka_oldest_event_age_seconds %g\n", healthy, stats.Count, stats.Bytes, age) - } - _, _ = fmt.Fprintf(w, "livepeer_signer_kafka_publish_errors_total %d\nlivepeer_signer_kafka_enqueue_errors_total %d\nlivepeer_signer_kafka_storage_errors_total %d\n", p.publishFailures.Load(), p.enqueueFailures.Load(), p.storageFailures.Load()) + emit("signer_kafka_pending_events", float64(stats.Count), nil) + emit("signer_kafka_pending_bytes", float64(stats.Bytes), nil) + emit("signer_kafka_oldest_event_age_seconds", age, nil) + } + emit("signer_kafka_publish_errors_total", float64(p.publishFailures.Load()), nil) + emit("signer_kafka_enqueue_errors_total", float64(p.enqueueFailures.Load()), nil) + emit("signer_kafka_storage_errors_total", float64(p.storageFailures.Load()), nil) + emit("signer_kafka_delivered_events_total", float64(p.deliveredEvents.Load()), observability.Labels{"component": "signer"}) + emit("signer_kafka_last_delivery_timestamp_seconds", float64(p.lastDelivery.Load()), observability.Labels{"component": "signer"}) } // Call after run has exited; network operations are bounded by the writer's diff --git a/signer/metrics.go b/signer/metrics.go new file mode 100644 index 0000000..a7983b3 --- /dev/null +++ b/signer/metrics.go @@ -0,0 +1,73 @@ +package signer + +import ( + "context" + "errors" + "math/big" + "time" + + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/pm" +) + +// Wire statuses are compatibility responses, not failure classifications: a +// precheck RPC outage is HTTP 400, and an authorization denial can be HTTP 5xx. +func paymentOutcome(err error) string { + switch { + case errors.Is(err, context.Canceled): + return "client_cancelled" + case errors.Is(err, errPaymentService): + return "error" + case errors.Is(err, errAuthorizationDenied): + return "rejected" + case errors.Is(err, pm.ErrRefreshRequired): + return "refresh_required" + case errors.Is(err, pm.ErrNoTickets): + return "no_payment_needed" + case errors.Is(err, pm.ErrPayerUnavailable): + return "rejected" + } + if _, ok := errors.AsType[paymentFailure](err); ok { + return "rejected" + } + return "error" +} + +func (s *Service) collectMetrics(emit observability.Emit) { + s.collector.CollectMetrics(emit) + if s.pricePolicy != nil { + s.pricePolicy.mu.RLock() + until := s.pricePolicy.validUntil + s.pricePolicy.mu.RUnlock() + value := 0.0 + if !until.IsZero() { + value = float64(until.Unix()) + } + emit("price_feed_valid_until_timestamp_seconds", value, nil) + emit("dependency_healthy", observability.Bool(s.pricePolicy.ready()), observability.Labels{"dependency": "price_feed"}) + } +} + +func (s *Service) signMessage(kind string, data []byte) ([]byte, error) { + sig, err := s.key.SignMessage(data) + s.metrics.Add("signer_sign_operations_total", 1, observability.Labels{"kind": kind, "outcome": observability.ErrorKind(err)}) + return sig, err +} + +func (s *Service) observeFunds(funds pm.PayerFunds, total bool) { + if funds.Snapshot.Block != nil && funds.Snapshot.Round != nil { + s.metrics.Gauge("chain_snapshot_last_success_timestamp_seconds", nil).Set(float64(time.Now().Unix())) + } + if funds.Snapshot.Block != nil { + s.metrics.Gauge("chain_snapshot_block", nil).Set(float64(funds.Snapshot.Block.Int64())) + } + if funds.Snapshot.Round != nil { + s.metrics.Gauge("chain_snapshot_round", nil).Set(float64(funds.Snapshot.Round.Int64())) + } + if funds.Deposit != nil { + s.metrics.Gauge("signer_deposit_eth", nil).Set(observability.ETH(new(big.Rat).SetInt(funds.Deposit))) + } + if total && funds.Reserve != nil { + s.metrics.Gauge("signer_reserve_eth", nil).Set(observability.ETH(new(big.Rat).SetInt(funds.Reserve))) + } +} diff --git a/signer/outbox_test.go b/signer/outbox_test.go index 216d9ac..570defe 100644 --- a/signer/outbox_test.go +++ b/signer/outbox_test.go @@ -1,12 +1,12 @@ package signer import ( - "bytes" "context" "encoding/json" "errors" "fmt" "io/fs" + "net/http/httptest" "os" "path/filepath" "sync" @@ -15,6 +15,8 @@ import ( "time" "uuid" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" "github.com/livepeer/node/nodeconfig/migrations" "github.com/segmentio/kafka-go" "github.com/stretchr/testify/require" @@ -157,10 +159,9 @@ func TestOutboxCapacityConcurrentAdmissionAndRecovery(t *testing.T) { require.NoError(t, p.Enqueue(t.Context(), testEvent())) require.False(t, p.ready(t.Context())) require.Equal(t, uint64(9), p.enqueueFailures.Load()) - var metrics bytes.Buffer - p.metrics(t.Context(), &metrics) + metrics := collectKafkaMetrics(t, p) for _, want := range []string{"pending_events 3", fmt.Sprintf("pending_bytes %d", len(raw)*3), "oldest_event_age_seconds", "enqueue_errors_total 9", "publish_errors_total 0"} { - require.Contains(t, metrics.String(), want) + require.Contains(t, metrics, want) } } @@ -174,13 +175,14 @@ func TestOutboxStorageWriteFailureAndRecovery(t *testing.T) { require.NoError(t, err) require.True(t, p.ready(t.Context()), "readiness must recover without requiring traffic") require.NoError(t, p.Enqueue(t.Context(), testEvent())) - var metrics bytes.Buffer - p.metrics(t.Context(), &metrics) - require.Contains(t, metrics.String(), "storage_errors_total 1") + metrics := collectKafkaMetrics(t, p) + require.Contains(t, metrics, "storage_errors_total 1") } func TestOutboxPartialDeliveryRetainsWholeBatch(t *testing.T) { p := testKafkaProducer(t, 1<<20) + m := observability.New("signer") + m.Legacy(p.collectMetrics) for range 3 { require.NoError(t, p.Enqueue(t.Context(), testEvent())) } @@ -204,6 +206,7 @@ func TestOutboxPartialDeliveryRetainsWholeBatch(t *testing.T) { retained, err := p.outbox.pending(t.Context()) require.NoError(t, err) require.Equal(t, original, retained) + require.Zero(t, test.MetricSum(t, m.Registry, "signer_kafka_delivered_events_total", nil)) progress, err := p.publish(t.Context()) require.NoError(t, err) require.True(t, progress) @@ -212,6 +215,12 @@ func TestOutboxPartialDeliveryRetainsWholeBatch(t *testing.T) { require.Zero(t, stats.Count) require.Zero(t, stats.Bytes) require.Equal(t, 2, calls) + require.EqualValues(t, 3, test.MetricSum(t, m.Registry, "signer_kafka_delivered_events_total", map[string]string{"component": "signer"})) + require.Positive(t, test.MetricSum(t, m.Registry, "signer_kafka_last_delivery_timestamp_seconds", map[string]string{"component": "signer"})) + require.Len(t, test.MetricSamples(t, m.Registry, "signer_kafka_pending_events", map[string]string{}), 1) + for _, label := range test.MetricSamples(t, m.Registry, "signer_kafka_pending_events", nil)[0].Label { + require.NotEqual(t, "component", label.GetName()) + } } func TestPublisherBatchingAndCancellation(t *testing.T) { @@ -265,3 +274,13 @@ func TestPublisherRetriesWithoutChangingEvent(t *testing.T) { require.GreaterOrEqual(t, second.Sub(first), time.Second) require.Equal(t, uint64(1), p.publishFailures.Load()) } + +func collectKafkaMetrics(t *testing.T, p *kafkaProducer) string { + t.Helper() + m := observability.New("signer") + m.Legacy(p.collectMetrics) + response := httptest.NewRecorder() + m.Handler().ServeHTTP(response, httptest.NewRequest("GET", "/metrics", nil)) + require.Equal(t, 200, response.Code, response.Body.String()) + return response.Body.String() +} diff --git a/signer/payment.go b/signer/payment.go index a5f8385..f3c55b0 100644 --- a/signer/payment.go +++ b/signer/payment.go @@ -4,7 +4,6 @@ import ( "context" "encoding/base64" "errors" - "fmt" "log/slog" "math" "math/big" @@ -13,6 +12,7 @@ import ( ethcommon "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm" "github.com/livepeer/node/pm/wire" ) @@ -104,17 +104,17 @@ func (s *Service) preparePayment(ctx context.Context, paymentType, manifest stri if errors.Is(err, pm.ErrRefreshRequired) { return draftPayment{}, err } - if f, ok := errors.AsType[paymentFailure](err); ok { - return draftPayment{}, f + if _, ok := errors.AsType[paymentFailure](err); ok { + return draftPayment{}, err } - return draftPayment{}, invalid("payer funds unavailable") + return draftPayment{}, errors.Join(invalid("payer funds unavailable"), err) } count, err := pm.RemoteBatchSize(params, fee, balance) if err != nil { if errors.Is(err, pm.ErrNoTickets) { return draftPayment{}, err } - slog.WarnContext(ctx, "signer ticket batch rejected", "error", err) + slog.With("component", "signer", "event", "payment", "operation", "payment").WarnContext(ctx, "signer ticket batch rejected", "outcome", "error", "error_kind", observability.ErrorKind(err)) return draftPayment{}, invalid("invalid ticket batch") } // Recheck the full batch before authorization. A later observation/funding failure @@ -125,7 +125,7 @@ func (s *Service) preparePayment(ctx context.Context, paymentType, manifest stri batch, remaining, err := pm.DraftRemoteBatch(params, s.key.Address(), state.TicketNonce, fee, balance) if err != nil { if !errors.Is(err, pm.ErrRefreshRequired) && !errors.Is(err, pm.ErrNoTickets) { - slog.ErrorContext(ctx, "signer ticket batch generation failed", "error", err) + slog.With("component", "signer", "event", "payment", "operation", "payment").ErrorContext(ctx, "signer ticket batch generation failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) } return draftPayment{}, err } @@ -153,13 +153,14 @@ func (s *Service) preparePayment(ctx context.Context, paymentType, manifest stri // Sign adds signatures to the exact payment prepared before authorization. // It does not observe the clock or chain, or recalculate any payment values. -func (p draftPayment) Sign(ctx context.Context, signer pm.TicketSigner) (signedPayment, error) { +func (p draftPayment) Sign(ctx context.Context, signer pm.TicketSigner, metrics *observability.Metrics) (signedPayment, error) { message := p.payment message.PayerParams = make([]wire.TicketPayerParams, 0, len(p.batch.PayerParams)) for _, ticket := range p.batch.Tickets() { sig, err := signer.SignMessage(ticket.Hash().Bytes()) + metrics.Add("signer_sign_operations_total", 1, observability.Labels{"kind": "ticket", "outcome": observability.ErrorKind(err)}) if err != nil { - slog.ErrorContext(ctx, "signer ticket batch generation failed", "error", err) + slog.With("component", "signer", "event", "payment", "operation", "payment").ErrorContext(ctx, "signer ticket batch generation failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) return signedPayment{}, err } message.PayerParams = append(message.PayerParams, wire.TicketPayerParams{TicketNonce: ticket.TicketNonce, Sig: sig}) @@ -167,8 +168,9 @@ func (p draftPayment) Sign(ctx context.Context, signer pm.TicketSigner) (signedP flatten := append(slices.Clone(p.segment.ManifestID), make([]byte, 32)...) flatten = append(flatten, p.segment.Hash...) sig, err := signer.SignMessage(crypto.Keccak256(flatten)) + metrics.Add("signer_sign_operations_total", 1, observability.Labels{"kind": "segment", "outcome": observability.ErrorKind(err)}) if err != nil { - slog.ErrorContext(ctx, "signer segment credential signing failed", "error", err) + slog.With("component", "signer", "event", "payment", "operation", "payment").ErrorContext(ctx, "signer segment credential signing failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) return signedPayment{}, err } segment := p.segment @@ -187,25 +189,26 @@ func (s *Service) validateTicketParams(ctx context.Context, ticketParams *pm.Tic return invalid("ticketParams expiration block is 0") } if s.paymentChain == nil { - slog.ErrorContext(ctx, "signer payer chain is not configured", "phase", phase) - return pm.ErrPayerUnavailable + slog.With("component", "signer", "event", "payment", "operation", "payment").ErrorContext(ctx, "signer payer chain is not configured", "phase", phase) + return errors.Join(pm.ErrPayerUnavailable, errPaymentService) } funds, err := s.paymentChain.PayerFunds(ctx, s.key.Address(), ticketParams.Recipient) if err != nil { - slog.ErrorContext(ctx, "signer payer chain observation failed", "phase", phase, "error", err) - return fmt.Errorf("%w: chain observation failed", pm.ErrPayerUnavailable) + slog.With("component", "signer", "event", "payment", "operation", "payment").ErrorContext(ctx, "signer payer chain observation failed", "phase", phase, "outcome", "error", "error_kind", observability.ErrorKind(err)) + return errors.Join(pm.ErrPayerUnavailable, errPaymentService) } if funds.Snapshot.Block == nil { - slog.ErrorContext(ctx, "signer payer chain observation has no L1 block", "phase", phase) - return fmt.Errorf("%w: chain observation failed", pm.ErrPayerUnavailable) + slog.With("component", "signer", "event", "payment", "operation", "payment").ErrorContext(ctx, "signer payer chain observation has no L1 block", "phase", phase) + return errors.Join(pm.ErrPayerUnavailable, errPaymentService) } + s.observeFunds(funds, false) latestL1Block := funds.Snapshot.Block currentBuffer := new(big.Int).Sub(ticketParams.ExpirationBlock, latestL1Block).Int64() if currentBuffer <= paramsExpiryBuffer { return pm.ErrRefreshRequired } if err := s.payerPolicy.Check(*ticketParams, numTickets, funds); err != nil { - slog.WarnContext(ctx, "signer payer policy rejected ticket parameters", "phase", phase, "num_tickets", numTickets, "error", err) + slog.With("component", "signer", "event", "payment", "operation", "payment").WarnContext(ctx, "signer payer policy rejected ticket parameters", "phase", phase, "num_tickets", numTickets, "outcome", "error", "error_kind", observability.ErrorKind(err)) if errors.Is(err, pm.ErrPayerUnavailable) { return err } diff --git a/signer/payment_test.go b/signer/payment_test.go index 4801b52..01db9f0 100644 --- a/signer/payment_test.go +++ b/signer/payment_test.go @@ -36,7 +36,7 @@ func TestPaymentEncoding(t *testing.T) { t.Run(kind, func(t *testing.T) { draft, err := s.preparePayment(t.Context(), kind, info.Auth.SessionID, info, paymentState{}, -1, time.Now()) require.NoError(t, err) - signed, err := draft.Sign(t.Context(), key) + signed, err := draft.Sign(t.Context(), key, nil) require.NoError(t, err) require.Equal(t, fixtures[kind].Payment, signed.Payment) require.Equal(t, fixtures[kind].SegCreds, signed.SegCreds) @@ -77,7 +77,7 @@ func TestDraftPaymentPreservesValues(t *testing.T) { } info.Price.PricePerUnit = 999 info.Auth.Expiration = 0 - signed, err := draft.Sign(t.Context(), s.key) + signed, err := draft.Sign(t.Context(), s.key, nil) require.NoError(t, err) paymentBytes, err := base64.StdEncoding.DecodeString(signed.Payment) require.NoError(t, err) @@ -129,7 +129,7 @@ func TestRecipientReservesWinningLiabilityAcrossConcurrentSessions(t *testing.T) require.NoError(t, err) draft, err := s.preparePayment(t.Context(), "fixed", manifest, info, paymentState{}, -1, time.Now()) require.NoError(t, err) - payment, err := draft.Sign(t.Context(), key) + payment, err := draft.Sign(t.Context(), key, nil) require.NoError(t, err) payments[manifest] = payment } diff --git a/signer/price.go b/signer/price.go index cf9bd57..6f2d528 100644 --- a/signer/price.go +++ b/signer/price.go @@ -8,12 +8,14 @@ import ( "sync" "time" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm/wire" ) // pricePolicy holds only a local observation of the exchange rate. Signer // replicas use the same configured limits and feed, without sharing state. type pricePolicy struct { + metrics *observability.Metrics mu sync.RWMutex maxLiveUSD, maxFixedUSD *big.Rat weiPerUSD *big.Rat @@ -65,7 +67,7 @@ func (p *pricePolicy) ready() bool { func (p *pricePolicy) checkWithRate(paymentType string, price wire.PriceInfo) (*big.Rat, error) { rate, ok := p.rate() if !ok { - return nil, paymentFailure{503, "signer USD conversion rate unavailable"} + return nil, serviceFailure(503, "signer USD conversion rate unavailable") } ceiling := p.maxLiveUSD if paymentType == "fixed" { @@ -86,15 +88,24 @@ func refreshPriceFeed(ctx context.Context, period time.Duration, policy *pricePo case <-ctx.Done(): return case <-ticker.C: - readCtx, cancel := context.WithTimeout(ctx, 30*time.Second) - rate, until, err := read(readCtx) - cancel() - if err == nil { - err = policy.setRate(rate, until) - } - if err != nil { - slog.Error("signer price feed unavailable", "error", err) - } + _ = policy.refreshFeed(ctx, read) } } } + +// Startup and scheduled reads each publish exactly one feed observation. +func (p *pricePolicy) refreshFeed(ctx context.Context, read func(context.Context) (*big.Rat, time.Time, error)) error { + readCtx, cancel := context.WithTimeout(ctx, 30*time.Second) + defer cancel() + rate, until, err := read(readCtx) + if err == nil { + err = p.setRate(rate, until) + } + if err == nil { + p.metrics.Add("price_feed_updates_total", 1, observability.Labels{"outcome": "success"}) + } else { + p.metrics.Add("price_feed_updates_total", 1, observability.Labels{"outcome": "error"}) + slog.With("component", "signer", "event", "price_feed", "operation", "refresh").Error("signer price feed unavailable; check --eth-usd-feed, --eth-usd-max-age and RPC configuration", "outcome", "error", "error_kind", observability.ErrorKind(err)) + } + return err +} diff --git a/signer/price_test.go b/signer/price_test.go index 574ddd2..b26b387 100644 --- a/signer/price_test.go +++ b/signer/price_test.go @@ -9,6 +9,8 @@ import ( "testing" "time" + "github.com/livepeer/node/internal/observability" + "github.com/livepeer/node/internal/test" "github.com/livepeer/node/pm/wire" "github.com/stretchr/testify/require" ) @@ -19,26 +21,33 @@ func (p *pricePolicy) check(paymentType string, price wire.PriceInfo) error { } func TestPricePolicyExactCeilingsAndRateExpiry(t *testing.T) { + status := func(err error) int { + var failure paymentFailure + require.ErrorAs(t, err, &failure) + return failure.status + } hourly := big.NewRat(1200, 1) // $1200/hour = $1/3 per second. p, err := newPricePolicy(hourly, testRat(t, "1/2")) require.NoError(t, err) + p.metrics = observability.New("signer") require.Equal(t, big.NewRat(1200, 1), hourly, "must not mutate configuration") require.False(t, p.ready()) - require.Equal(t, 503, p.check("live", wire.PriceInfo{PricePerUnit: 1, UnitsPerPrice: 1}).(paymentFailure).status) + require.Equal(t, 503, status(p.check("live", wire.PriceInfo{PricePerUnit: 1, UnitsPerPrice: 1}))) require.NoError(t, p.setRate(big.NewRat(3, 1), time.Now().Add(time.Minute))) require.True(t, p.ready()) require.NoError(t, p.check("live", wire.PriceInfo{PricePerUnit: 1, UnitsPerPrice: 1})) - require.Equal(t, 481, p.check("live", wire.PriceInfo{PricePerUnit: 4, UnitsPerPrice: 3}).(paymentFailure).status) + require.Equal(t, 481, status(p.check("live", wire.PriceInfo{PricePerUnit: 4, UnitsPerPrice: 3}))) require.NoError(t, p.check("fixed", wire.PriceInfo{PricePerUnit: 3, UnitsPerPrice: 2})) - require.Equal(t, 481, p.check("fixed", wire.PriceInfo{PricePerUnit: 5, UnitsPerPrice: 3}).(paymentFailure).status) + require.Equal(t, 481, status(p.check("fixed", wire.PriceInfo{PricePerUnit: 5, UnitsPerPrice: 3}))) require.NoError(t, p.setRate(big.NewRat(6, 1), time.Now().Add(time.Minute))) require.NoError(t, p.check("live", wire.PriceInfo{PricePerUnit: 2, UnitsPerPrice: 1}), "refreshed rate must take effect") p.mu.Lock() p.validUntil = time.Now().Add(-time.Second) p.mu.Unlock() require.False(t, p.ready()) - require.Equal(t, 503, p.check("fixed", wire.PriceInfo{PricePerUnit: 1, UnitsPerPrice: 1}).(paymentFailure).status) + require.Equal(t, 503, status(p.check("fixed", wire.PriceInfo{PricePerUnit: 1, UnitsPerPrice: 1}))) require.Error(t, p.setRate(big.NewRat(6, 1), time.Now().Add(-time.Second))) + require.Zero(t, test.MetricSum(t, p.metrics.Registry, "price_feed_updates_total", nil), "local rate configuration is not a feed read") } func TestSignerUnavailableFeedThenRefresh(t *testing.T) { @@ -46,6 +55,16 @@ func TestSignerUnavailableFeedThenRefresh(t *testing.T) { policy, err := newPricePolicy(new(big.Rat).Mul(testRat(t, "20"), big.NewRat(3600, 1)), testRat(t, "20")) require.NoError(t, err) s.pricePolicy = policy + policy.metrics = s.metrics + // The same read path runs once at startup, before the recurring worker. + require.Error(t, policy.refreshFeed(t.Context(), func(context.Context) (*big.Rat, time.Time, error) { + return nil, time.Time{}, errors.New("feed unavailable") + })) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "price_feed_updates_total", map[string]string{"outcome": "error"})) + require.Error(t, policy.refreshFeed(t.Context(), func(context.Context) (*big.Rat, time.Time, error) { + return big.NewRat(0, 1), time.Time{}, nil + })) + require.EqualValues(t, 2, test.MetricSum(t, s.metrics.Registry, "price_feed_updates_total", map[string]string{"outcome": "error"})) req := map[string]any{"orchestrator": wire.EncodeOrchestratorInfo(info), "type": "fixed"} require.Equal(t, 503, postPayment(t, s, req).Code) require.False(t, policy.ready()) @@ -68,7 +87,12 @@ func TestSignerUnavailableFeedThenRefresh(t *testing.T) { require.Equal(t, 200, postPayment(t, s, req).Code) cancel() <-done - require.NoError(t, policy.setRate(big.NewRat(1, 1), time.Now().Add(10*time.Millisecond))) + require.Positive(t, test.MetricSum(t, s.metrics.Registry, "price_feed_updates_total", map[string]string{"outcome": "success"})) + before := test.MetricSum(t, s.metrics.Registry, "price_feed_updates_total", map[string]string{"outcome": "success"}) + require.NoError(t, policy.refreshFeed(t.Context(), func(context.Context) (*big.Rat, time.Time, error) { + return big.NewRat(1, 1), time.Now().Add(10 * time.Millisecond), nil + })) + require.Equal(t, before+1, test.MetricSum(t, s.metrics.Registry, "price_feed_updates_total", map[string]string{"outcome": "success"})) require.Eventually(t, func() bool { return !policy.ready() }, time.Second, time.Millisecond) require.Equal(t, 503, postPayment(t, s, req).Code) } diff --git a/signer/service.go b/signer/service.go index 7c0cca0..043acb8 100644 --- a/signer/service.go +++ b/signer/service.go @@ -17,9 +17,11 @@ import ( "time" ethcommon "github.com/ethereum/go-ethereum/common" + "github.com/felixge/httpsnoop" "github.com/livepeer/node/destination" discovery "github.com/livepeer/node/discovery/shared" "github.com/livepeer/node/eth" + "github.com/livepeer/node/internal/observability" "github.com/livepeer/node/pm" "github.com/livepeer/node/pm/wire" ) @@ -45,6 +47,7 @@ type paymentResponse struct { } type Service struct { + metrics *observability.Metrics authClient *http.Client authURL *url.URL authPolicy string @@ -92,7 +95,7 @@ func (s *Service) SetDiscovery(orchestrators []*url.URL, grants ...string) error client := policy.Client() client.Timeout = 5 * time.Second s.collector.Close() - s.collector = &discovery.Collector[discoveredRunner]{Client: client, MaxFailures: s.collector.MaxFailures} + s.collector = &discovery.Collector[discoveredRunner]{Client: client, MaxFailures: s.collector.MaxFailures, Observe: s.metrics.Discovery} if s.orchWebhook == nil { s.collector.SetSources(urls) } else if cached := s.orchWebhook.urls.Load(); cached != nil { @@ -142,6 +145,7 @@ func (s *Service) Close() error { func newService(key *eth.Key) *Service { s := &Service{ + metrics: observability.New("signer"), key: key, mux: http.NewServeMux(), payerPolicy: pm.DefaultPayerPolicy(), @@ -152,9 +156,17 @@ func newService(key *eth.Key) *Service { s.mux.HandleFunc("POST /sign-orchestrator-info", s.signInfo) s.mux.HandleFunc("POST /generate-live-payment", s.generate) s.mux.HandleFunc("GET /discover-orchestrators", s.discover) + s.metrics.Snapshot(s.collectMetrics) + s.metrics.Legacy(func(emit observability.Emit) { emit("signer_up", 1, nil) }) return s } func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) { + s.metrics.HTTP(w, r, s.serveHTTP) +} + +func (s *Service) serveHTTP(w http.ResponseWriter, r *http.Request) { + _, pattern := s.mux.Handler(r) + observability.Operation(r, pattern) ctx, cancel := context.WithTimeout(r.Context(), 30*time.Second) defer cancel() control := http.NewResponseController(w) @@ -175,6 +187,7 @@ func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) { case s.slots <- struct{}{}: defer func() { <-s.slots }() default: + s.metrics.Add("http_admission_rejections_total", 1, observability.Labels{"pool": "control"}) signerError(w, http.StatusServiceUnavailable, "signer busy") return } @@ -193,9 +206,9 @@ func signerError(w http.ResponseWriter, status int, reason string) { func (s *Service) signInfo(w http.ResponseWriter, r *http.Request) { address := s.key.Address().Hex() - sig, err := s.key.SignMessage([]byte(address)) + sig, err := s.signMessage("orchestrator_info", []byte(address)) if err != nil { - slog.ErrorContext(r.Context(), "signer orchestrator info signing failed", "error", err) + slog.With("component", "signer", "event", "sign_payment", "operation", "sign_payment").ErrorContext(r.Context(), "signer orchestrator info signing failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) signerError(w, 500, "signing failed") return } @@ -302,6 +315,15 @@ type paymentFailure struct { func (e paymentFailure) Error() string { return e.reason } func invalid(reason string) error { return paymentFailure{http.StatusBadRequest, reason} } +var ( + errPaymentService = errors.New("payment dependency unavailable") + errAuthorizationDenied = errors.New("payment authorization denied") +) + +func serviceFailure(status int, reason string) error { + return errors.Join(paymentFailure{status, reason}, errPaymentService) +} + func checkMaxPrice(req paymentRequest, price wire.PriceInfo) error { if req.MaxPrice == nil { return nil @@ -322,7 +344,17 @@ func checkMaxPrice(req paymentRequest, price wire.PriceInfo) error { } func (s *Service) generate(w http.ResponseWriter, r *http.Request) { - body, err := io.ReadAll(http.MaxBytesReader(w, r.Body, 1<<20)) + paymentType, outcome := "unknown", "rejected" + defer func() { + if outcome != "success" && errors.Is(r.Context().Err(), context.Canceled) { + outcome = "client_cancelled" + } else if outcome != "success" && errors.Is(r.Context().Err(), context.DeadlineExceeded) { + outcome = "error" + } + s.metrics.Add("signer_payments_total", 1, observability.Labels{"type": paymentType, "outcome": outcome}) + }() + // MaxBytesReader needs net/http's original writer to close oversized requests. + body, err := io.ReadAll(http.MaxBytesReader(httpsnoop.Unwrap(w), r.Body, 1<<20)) if err != nil { signerError(w, 400, "payment request too large") return @@ -336,6 +368,7 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { signerError(w, 400, "payment type must be live or fixed") return } + paymentType = req.Type info, err := wire.DecodeOrchestratorInfo(req.Orchestrator) if err != nil { signerError(w, 400, "invalid orchestrator Protobuf") @@ -350,6 +383,7 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { authTokenExpireBuffer := 0.1 refreshPoint := info.Auth.Expiration - int64(authTokenValidPeriod.Seconds()*authTokenExpireBuffer) if time.Now().After(time.Unix(refreshPoint, 0)) { + outcome = "refresh_required" w.Header().Set("Livepeer-Orchestrator-URL", info.Transcoder) signerError(w, 480, "refresh expired orchestrator authentication") return @@ -374,7 +408,8 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { var err error accountingRate, err = s.pricePolicy.checkWithRate(req.Type, info.Price) if err != nil { - f := err.(paymentFailure) + outcome = paymentOutcome(err) + f, _ := errors.AsType[paymentFailure](err) signerError(w, f.status, f.reason) return } @@ -404,6 +439,7 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { } draft, err := s.preparePayment(r.Context(), req.Type, req.ManifestID, info, state, oldSequence, time.Now()) if err != nil { + outcome = paymentOutcome(err) switch { case errors.Is(err, pm.ErrRefreshRequired): w.Header().Set("Livepeer-Orchestrator-URL", info.Transcoder) @@ -425,6 +461,7 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { draft.State.FeeUSD = new(strings.TrimSuffix(strings.TrimRight(value, "0"), ".")) } if err := s.authorizePayment(r, req, info.Price, &draft.State); err != nil { + outcome = paymentOutcome(err) if f, ok := errors.AsType[paymentFailure](err); ok { signerError(w, f.status, f.reason) } else { @@ -432,26 +469,27 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { } return } - signed, err := draft.Sign(r.Context(), s.key) + outcome = "error" + signed, err := draft.Sign(r.Context(), s.key, s.metrics) if err != nil { signerError(w, 500, "payment generation failed") return } stateBytes, err := json.Marshal(draft.State) if err != nil { - slog.ErrorContext(r.Context(), "signer payment state encoding failed", "error", err) + slog.With("component", "signer", "event", "sign_payment", "operation", "sign_payment").ErrorContext(r.Context(), "signer payment state encoding failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) signerError(w, 500, "payment state encoding failed") return } - stateSig, err := s.key.SignMessage(stateBytes) + stateSig, err := s.signMessage("state", stateBytes) if err != nil { - slog.ErrorContext(r.Context(), "signer payment state signing failed", "error", err) + slog.With("component", "signer", "event", "sign_payment", "operation", "sign_payment").ErrorContext(r.Context(), "signer payment state signing failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) signerError(w, 500, "payment state signing failed") return } response, err := json.Marshal(paymentResponse{Payment: signed.Payment, SegCreds: signed.SegCreds, State: signedState{State: stateBytes, Sig: stateSig}}) if err != nil { - slog.ErrorContext(r.Context(), "signer payment response encoding failed", "error", err) + slog.With("component", "signer", "event", "sign_payment", "operation", "sign_payment").ErrorContext(r.Context(), "signer payment response encoding failed", "outcome", "error", "error_kind", observability.ErrorKind(err)) signerError(w, 500, "payment response encoding failed") return } @@ -459,10 +497,11 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { event := newSignedTicketEvent(s.key.Address(), req, info, draft) if err := s.events.Enqueue(r.Context(), event); err != nil { if errors.Is(err, errEventTooLarge) { - slog.WarnContext(r.Context(), "signer accounting event exceeds size limit; payment withheld", "error", err) + outcome = "rejected" + slog.With("component", "signer", "event", "sign_payment", "operation", "sign_payment").WarnContext(r.Context(), "signer accounting event exceeds size limit; payment withheld", "outcome", "error", "error_kind", observability.ErrorKind(err)) signerError(w, http.StatusRequestEntityTooLarge, "signing event exceeds size limit") } else { - slog.ErrorContext(r.Context(), "signer accounting event could not be persisted; payment withheld", "outbox_full", errors.Is(err, errOutboxFull), "error", err) + slog.With("component", "signer", "event", "sign_payment", "operation", "sign_payment").ErrorContext(r.Context(), "signer accounting event could not be persisted; payment withheld", "outbox_full", errors.Is(err, errOutboxFull), "outcome", "error", "error_kind", observability.ErrorKind(err)) signerError(w, http.StatusServiceUnavailable, "signer accounting outbox unavailable or full") } return @@ -470,4 +509,6 @@ func (s *Service) generate(w http.ResponseWriter, r *http.Request) { } w.Header().Set("Content-Type", "application/json") _, _ = w.Write(response) + outcome = "success" + s.metrics.Add("signer_tickets_total", float64(draft.Usage.NumTickets), observability.Labels{"type": req.Type}) } diff --git a/signer/service_test.go b/signer/service_test.go index 6990656..10c4e57 100644 --- a/signer/service_test.go +++ b/signer/service_test.go @@ -7,6 +7,7 @@ import ( "encoding/json" "errors" "fmt" + "io" "log/slog" "math/big" "net" @@ -91,6 +92,23 @@ func postPayment(t *testing.T, s *Service, request map[string]any) *httptest.Res return w } +func TestOversizedPaymentRequestClosesConnection(t *testing.T) { + s, _ := testService(t) + defer s.Close() + countingKey := &failingPaymentSigner{TicketSigner: s.key} + s.key = countingKey + server := httptest.NewServer(s) + defer server.Close() + response, err := http.Post(server.URL+"/generate-live-payment", "application/json", strings.NewReader(strings.Repeat("x", (1<<20)+1))) + require.NoError(t, err) + defer response.Body.Close() + body, err := io.ReadAll(response.Body) + require.NoError(t, err) + require.Equal(t, http.StatusBadRequest, response.StatusCode, string(body)) + require.True(t, response.Close, "oversized bodies must retire the HTTP connection") + require.Zero(t, countingKey.calls.Load()) +} + func requirePaymentFailure(t *testing.T, w *httptest.ResponseRecorder, status int) { t.Helper() require.Equal(t, status, w.Code, w.Body.String()) @@ -258,6 +276,7 @@ func TestSignerRejectsCarriedCreditWithoutTickets(t *testing.T) { request["orchestrator"], request["state"] = wire.EncodeOrchestratorInfo(info), first.State response = postPayment(t, s, request) requirePaymentFailure(t, response, 482) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": "no_payment_needed"})) } func TestSlowResponseReleasesSlotOnDeadlineOrCancellation(t *testing.T) { @@ -311,6 +330,7 @@ func TestSignerRefreshResetsNonceAtBatchLimit(t *testing.T) { } require.Equal(t, uint32(500), state.TicketNonce) require.Equal(t, 480, postPayment(t, s, req).Code, "exhausted parameters must request a refresh") + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": "refresh_required"})) info.TicketParams.RecipientRandHash = crypto.Keccak256([]byte("fresh recipient randomness")) req["orchestrator"] = wire.EncodeOrchestratorInfo(info) w := postPayment(t, s, req) @@ -428,13 +448,19 @@ func TestPaymentFailureStatuses(t *testing.T) { } return funds, err })) + outcome := "rejected" + if cause == "chain observation" { + outcome = "error" + } + before := test.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": outcome}) response := postPayment(t, s, map[string]any{"orchestrator": wire.EncodeOrchestratorInfo(original), "type": "fixed"}) requirePaymentFailure(t, response, phase.status) + require.Equal(t, before+1, test.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": outcome})) require.NotContains(t, response.Body.String(), "rpc.internal") require.NotContains(t, response.Body.String(), "private-rpc-detail") require.Contains(t, logs.String(), `"phase":"`+phase.name+`"`) if cause == "chain observation" { - require.Contains(t, logs.String(), "RPC https://rpc.internal/?token=private-rpc-detail failed") + require.NotContains(t, logs.String(), "private-rpc-detail") } }) } @@ -464,7 +490,7 @@ func TestPaymentFailureStatuses(t *testing.T) { require.NotContains(t, response.Body.String(), "/private/keys") require.NotContains(t, response.Body.String(), "private-signing-detail") require.Contains(t, logs.String(), tc.log) - require.Contains(t, logs.String(), "key /private/keys/signer.json: private-signing-detail") + require.NotContains(t, logs.String(), "private-signing-detail") }) } s.key = key @@ -484,7 +510,27 @@ func TestPaymentFailureStatuses(t *testing.T) { require.NotContains(t, response.Body.String(), "/private/accounting.sqlite") require.NotContains(t, response.Body.String(), "private-storage-detail") require.Contains(t, logs.String(), "payment withheld") - require.Contains(t, logs.String(), tc.err.Error()) + require.NotContains(t, logs.String(), "private-storage-detail") + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": "success"})) + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "signer_tickets_total", nil)) }) } } + +func TestCancelledPaymentOutcome(t *testing.T) { + s, info := testService(t) + defer s.Close() + s.SetPaymentChain(payerChainFunc(func(ctx context.Context, _, _ ethcommon.Address) (pm.PayerFunds, error) { + return pm.PayerFunds{}, ctx.Err() + })) + body, err := json.Marshal(map[string]any{"orchestrator": wire.EncodeOrchestratorInfo(info), "type": "fixed"}) + require.NoError(t, err) + ctx, cancel := context.WithCancel(t.Context()) + cancel() + request := httptest.NewRequest("POST", "/generate-live-payment", bytes.NewReader(body)).WithContext(ctx) + response := httptest.NewRecorder() + s.ServeHTTP(response, request) + requirePaymentFailure(t, response, 400) + require.EqualValues(t, 1, test.MetricSum(t, s.metrics.Registry, "signer_payments_total", map[string]string{"outcome": "client_cancelled"})) + require.Zero(t, test.MetricSum(t, s.metrics.Registry, "signer_tickets_total", nil)) +} diff --git a/trickle/local_publisher.go b/trickle/local_publisher.go index 98d222d..902c011 100644 --- a/trickle/local_publisher.go +++ b/trickle/local_publisher.go @@ -6,6 +6,8 @@ import ( "log/slog" "sync" "time" + + "github.com/livepeer/node/internal/observability" ) // local (in-memory) publisher for trickle protocol @@ -76,7 +78,7 @@ func (c *TrickleLocalPublisher) Write(data io.Reader) error { if err == io.EOF { break } - slog.Info("Error reading published data", "channel", c.channelName, "seq", seq, "bytes written", totalRead, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Error reading published data", "channel", c.channelName, "seq", seq, "bytes written", totalRead, "outcome", "error", "error_kind", observability.ErrorKind(err)) } } segment.close() diff --git a/trickle/local_subscriber.go b/trickle/local_subscriber.go index ed7bb3d..aa85ea4 100644 --- a/trickle/local_subscriber.go +++ b/trickle/local_subscriber.go @@ -6,6 +6,8 @@ import ( "log/slog" "strconv" "sync" + + "github.com/livepeer/node/internal/observability" ) // local (in-memory) subscriber for trickle protocol @@ -59,11 +61,11 @@ func (c *TrickleLocalSubscriber) Read() (*TrickleData, error) { data, eof := subscriber.readData() n, err := w.Write(data) if err != nil { - slog.Info("Error writing", "channel", c.channelName, "seq", segment.idx, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Error writing", "channel", c.channelName, "seq", segment.idx, "outcome", "error", "error_kind", observability.ErrorKind(err)) return } if n != len(data) { - slog.Info("Did not write enough data to local subscriber", "channel", c.channelName, "seq", segment.idx) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Did not write enough data to local subscriber", "channel", c.channelName, "seq", segment.idx) return } if eof { diff --git a/trickle/local_subscriber_test.go b/trickle/local_subscriber_test.go index db72cdd..c8c3183 100644 --- a/trickle/local_subscriber_test.go +++ b/trickle/local_subscriber_test.go @@ -97,37 +97,28 @@ func TestLocalSubscriber_PreconnectOnEmpty(t *testing.T) { defer pub.Close() sub := NewLocalSubscriber(server, "testest") - done := make(chan struct{}) - - go func() { - defer close(done) - require.Nil(pub.Write(bytes.NewReader([]byte("hello")))) - require.Nil(pub.Close()) - }() - - setSeqCount := 0 - - for i := 0; ; i++ { + for seq, payload := range []string{"hello", ""} { + // Select the next segment before the publisher can advance past it. sub.SetSeq(-1) td, err := sub.Read() - if err != nil && err.Error() == "stream not found" { - // would be better if this would be EOS but roll with it for now - break - } require.Nil(err) - require.Equal(strconv.Itoa(setSeqCount), td.Metadata["Lp-Trickle-Seq"]) + require.Equal(strconv.Itoa(seq), td.Metadata["Lp-Trickle-Seq"]) + require.Nil(pub.Write(bytes.NewReader([]byte(payload)))) n, err := io.Copy(io.Discard, td.Reader) require.Nil(err) - if i == 0 { - require.Equal(5, int(n)) // first post - "hello" - } else { - // second post (preconnect) is cancelled, completed as a zero-byte segment - require.Equal(0, int(n)) - } - setSeqCount++ + require.Equal(len(payload), int(n)) } - <-done - require.Equal(2, setSeqCount) + // The empty write advanced the sequence; closing releases its next preconnect. + sub.SetSeq(-1) + td, err := sub.Read() + require.Nil(err) + require.Equal("2", td.Metadata["Lp-Trickle-Seq"]) + require.Nil(pub.Close()) + n, err := io.Copy(io.Discard, td.Reader) + require.Nil(err) + require.Zero(n) + _, err = sub.Read() + require.EqualError(err, "stream not found") } diff --git a/trickle/trickle_publisher.go b/trickle/trickle_publisher.go index 1843a9d..4a671f5 100644 --- a/trickle/trickle_publisher.go +++ b/trickle/trickle_publisher.go @@ -9,6 +9,8 @@ import ( "net/http" "sync" "time" + + "github.com/livepeer/node/internal/observability" ) //lint:ignore ST1012 Preserve the public go-livepeer trickle API. @@ -81,13 +83,13 @@ func (c *TricklePublisher) preconnect() (*pendingPost, error) { index := c.index url := fmt.Sprintf("%s/%d", c.baseURL, index) - slog.Debug("Preconnecting", "url", url) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Preconnecting") errCh := make(chan error, 1) pr, pw := io.Pipe() req, err := http.NewRequest("POST", url, pr) if err != nil { - slog.Error("Failed to create request for segment", "url", url, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Failed to create request for segment", "outcome", "error", "error_kind", observability.ErrorKind(err)) return nil, err } req.Header.Set("Content-Type", c.contentType) @@ -97,7 +99,7 @@ func (c *TricklePublisher) preconnect() (*pendingPost, error) { go func() { resp, err := httpclient.Do(req) if err != nil { - slog.Error("Failed to complete POST for segment", "url", url, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Failed to complete POST for segment", "outcome", "error", "error_kind", observability.ErrorKind(err)) _ = pr.CloseWithError(err) errCh <- err return @@ -105,7 +107,7 @@ func (c *TricklePublisher) preconnect() (*pendingPost, error) { isEOS := resp.Header.Get("Lp-Trickle-Closed") != "" body, err := io.ReadAll(resp.Body) if err != nil && !isEOS { - slog.Error("Error reading body", "url", url, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Error reading body", "outcome", "error", "error_kind", observability.ErrorKind(err)) errCh <- err return } @@ -117,7 +119,7 @@ func (c *TricklePublisher) preconnect() (*pendingPost, error) { } if resp.StatusCode != http.StatusOK { - slog.Error("Failed POST segment", "url", url, "status_code", resp.StatusCode, "msg", string(body)) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Failed POST segment", "status_code", resp.StatusCode) if resp.StatusCode == http.StatusNotFound { errCh <- StreamNotFoundErr return @@ -127,7 +129,7 @@ func (c *TricklePublisher) preconnect() (*pendingPost, error) { return } } else { - slog.Debug("Uploaded segment", "url", url) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Uploaded segment") } errCh <- nil }() @@ -245,7 +247,7 @@ func (p *pendingPost) Write(data io.Reader) (int64, error) { // if no io errors, close the writer var closeErr error if ioError == nil { - slog.Debug("Completed writing", "idx", index, "totalBytes", humanBytes(n)) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Completed writing", "idx", index, "totalBytes", humanBytes(n)) // Close the pipe writer to signal end of data for the current POST request closeErr = writer.Close() diff --git a/trickle/trickle_server.go b/trickle/trickle_server.go index 14691a9..e9eea63 100644 --- a/trickle/trickle_server.go +++ b/trickle/trickle_server.go @@ -15,6 +15,8 @@ import ( "sync" "sync/atomic" "time" + + "github.com/livepeer/node/internal/observability" ) const CHANGEFEED = "_changes" @@ -62,6 +64,23 @@ type Server struct { internalPub *TrickleLocalPublisher } +// BufferedBytes reports published bytes retained by live channel segments. +func (sm *Server) BufferedBytes() int64 { + sm.mutex.RLock() + defer sm.mutex.RUnlock() + var size int64 + for _, stream := range sm.streams { + stream.mutex.RLock() + for _, segment := range stream.segments { + if segment != nil { + size += segment.buffer.published.Load() + } + } + stream.mutex.RUnlock() + } + return size +} + type Stream struct { mutex sync.RWMutex segments []*Segment @@ -211,7 +230,7 @@ func (sm *Server) getOrCreateStream(streamName, mimeType string, forceCreate boo maxSegmentBytes: sm.config.MaxSegmentBytes, } sm.streams[streamName] = stream - slog.Info("Creating stream", "stream", streamName) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Info("Creating stream", "stream", streamName) } sm.mutex.Unlock() @@ -257,9 +276,9 @@ func (sm *Server) sweepIdleChannels() { s.mutex.Unlock() if now.Sub(writeTime) > sm.config.IdleTimeout { if err := sm.closeStream(s.name); err != nil { - slog.Warn("Could not close idle channel", "channel", s.name, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Warn("Could not close idle channel", "channel", s.name, "outcome", "error", "error_kind", observability.ErrorKind(err)) } else { - slog.Info("Closed idle channel", "channel", s.name) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Info("Closed idle channel", "channel", s.name) } } } @@ -287,7 +306,7 @@ func (sm *Server) closeStream(streamName string) error { sm.mutex.Lock() delete(sm.streams, streamName) sm.mutex.Unlock() - slog.Info("Deleted stream", "streamName", streamName) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Info("Deleted stream", "streamName", streamName) // update changefeed if needed if !sm.config.Changefeed { @@ -328,7 +347,7 @@ func (sm *Server) closeSeq(w http.ResponseWriter, r *http.Request) { http.Error(w, "Invalid idx", http.StatusBadRequest) return } - slog.Info("DELETE closing seq", "channel", s.name, "seq", idx) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("DELETE closing seq", "channel", s.name, "seq", idx) s.mutex.RLock() seg := s.segments[idx%maxSegmentsPerStream] s.mutex.RUnlock() @@ -526,7 +545,7 @@ func (s *Stream) handlePost(w http.ResponseWriter, r *http.Request, idx int) { if err != nil { if err == FirstByteTimeout { // Keepalive via provisional headers - slog.Info("Sending provisional headers for", "stream", s.name, "idx", idx) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Sending provisional headers for", "stream", s.name, "idx", idx) w.WriteHeader(http.StatusContinue) continue } else if err == io.EOF { @@ -552,7 +571,7 @@ func (s *Stream) handlePost(w http.ResponseWriter, r *http.Request, idx int) { } break } - slog.Info("Error reading POST body", "stream", s.name, "idx", idx, "bytes written", totalRead, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Error reading POST body", "stream", s.name, "idx", idx, "bytes written", totalRead, "outcome", "error", "error_kind", observability.ErrorKind(err)) http.Error(w, "Server error", http.StatusInternalServerError) return } @@ -562,7 +581,7 @@ func (s *Stream) handlePost(w http.ResponseWriter, r *http.Request, idx int) { w.Header().Set("Lp-Trickle-Seq", strconv.Itoa(segment.idx)) stopInterrupt() segment.close() - slog.Info("POST completed", "stream", s.name, "idx", idx, "bytes", totalRead, "took", time.Since(startedAt)) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("POST completed", "stream", s.name, "idx", idx, "bytes", totalRead, "took", time.Since(startedAt)) } func (s *Stream) getForWrite(idx int) (*Segment, bool) { @@ -571,7 +590,7 @@ func (s *Stream) getForWrite(idx int) (*Segment, bool) { if idx == -1 { idx = s.nextWrite } - slog.Info("POST segment", "stream", s.name, "idx", idx, "next", s.nextWrite) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("POST segment", "stream", s.name, "idx", idx, "next", s.nextWrite) segmentPos := idx % maxSegmentsPerStream if segment := s.segments[segmentPos]; segment != nil { if idx == segment.idx { @@ -609,9 +628,9 @@ func (s *Stream) getForRead(idx int) (*Segment, int, bool, bool) { // read request is just a little bit ahead of write head segment = newSegment(idx, s.maxSegmentBytes) s.segments[segmentPos] = segment - slog.Info("GET precreating", "stream", s.name, "idx", idx, "next", s.nextWrite) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("GET precreating", "stream", s.name, "idx", idx, "next", s.nextWrite) } - slog.Info("GET segment", "stream", s.name, "idx", idx, "next", s.nextWrite, "exists?", exists(segment, idx)) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("GET segment", "stream", s.name, "idx", idx, "next", s.nextWrite, "exists?", exists(segment, idx)) return segment, s.nextWrite, exists(segment, idx), s.closed } @@ -721,7 +740,7 @@ func (s *Stream) handleGet(w http.ResponseWriter, r *http.Request, idx int) { if n, err := sendData(); err != nil { // Handle write error or client disconnect - slog.Error("Error sending data to client", "stream", s.name, "idx", segment.idx, "sentBytes", n, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Error sending data to client", "stream", s.name, "idx", segment.idx, "sentBytes", n, "outcome", "error", "error_kind", observability.ErrorKind(err)) return } } @@ -756,7 +775,7 @@ func (segment *Segment) writeData(data []byte) error { func (s *Segment) readData(readPos int) ([]byte, int, bool) { data, nextPos, atTail, invalid, _ := s.buffer.readChunk(readPos) if invalid { - slog.Info("Invalid start pos, invoking eof") + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Invalid start pos, invoking eof") return nil, readPos, true } if len(data) > 0 { @@ -777,7 +796,7 @@ func (s *Segment) readData(readPos int) ([]byte, int, bool) { return data, nextPos, s.closed && atTail && nextPos == published } if invalid { - slog.Info("Invalid start pos, invoking eof") + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("Invalid start pos, invoking eof") // This might happen if the buffer was reset // eg because of a repeated POST return nil, readPos, true diff --git a/trickle/trickle_subscriber.go b/trickle/trickle_subscriber.go index cd1d2a0..e51409e 100644 --- a/trickle/trickle_subscriber.go +++ b/trickle/trickle_subscriber.go @@ -10,6 +10,8 @@ import ( "strconv" "sync" "time" + + "github.com/livepeer/node/internal/observability" ) type SequenceStart int @@ -152,11 +154,11 @@ func (c *TrickleSubscriber) SetSeq(seq int) { func (c *TrickleSubscriber) connect(ctx context.Context) (*http.Response, error) { url := fmt.Sprintf("%s/%d", c.url, c.idx) - slog.Debug("preconnecting", "url", url) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("preconnecting") req, err := http.NewRequestWithContext(ctx, "GET", url, nil) if err != nil { - slog.Error("Failed to create request for segment", "url", url, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Failed to create request for segment", "outcome", "error", "error_kind", observability.ErrorKind(err)) return nil, err } @@ -246,7 +248,7 @@ func (c *TrickleSubscriber) Read() (*http.Response, error) { // TODO clean up this preconnect error handling! hitMaxPreconnects := c.preconnectErrorCount > 5 if hitMaxPreconnects { - slog.Error("Hit max preconnect error", "url", c.url, "idx", c.idx) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("Hit max preconnect error", "idx", c.idx) return nil, fmt.Errorf("hit max preconnects") } @@ -254,7 +256,7 @@ func (c *TrickleSubscriber) Read() (*http.Response, error) { conn := c.pendingGet if conn == nil { // Preconnect if we don't have a pending GET - slog.Debug("No preconnect, connecting", "url", c.url, "idx", c.idx) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Debug("No preconnect, connecting", "idx", c.idx) p, err := c.preconnect() if err != nil { c.preconnectErrorCount++ @@ -292,7 +294,7 @@ func (c *TrickleSubscriber) Read() (*http.Response, error) { defer c.mu.Unlock() nextConn, err := c.preconnect() if err != nil { - slog.Error("failed to preconnect next segment", "url", c.url, "idx", c.idx, "err", err) + slog.With("component", "trickle", "event", "stream", "operation", "stream").Error("failed to preconnect next segment", "idx", c.idx, "outcome", "error", "error_kind", observability.ErrorKind(err)) c.preconnectErrorCount++ return }