Repository navigation
feat(flags): monitor flag_evaluations parity against events #92749
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
ddfe314
f2e75ce
6a44047
d19456c
2f374ff
f54cde3
a895bde
3bcc375
333319f
1abf277
2552e5f
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,4 +1,4 @@ | ||
| import { Counter, Gauge } from 'prom-client' | ||
| import { Counter, Gauge, Histogram } from 'prom-client' | ||
|
|
||
| import { FLAG_EVALUATIONS_OUTPUT, FlagEvaluationsOutput } from '~/common/outputs' | ||
| import { IngestionOutputs } from '~/common/outputs/ingestion-outputs' | ||
|
|
@@ -34,6 +34,18 @@ export const flagEvaluationsPendingAcks = new Gauge({ | |
| help: 'flag_evaluations produces queued but not yet acknowledged; sustained non-zero means the fork is holding up batches', | ||
| }) | ||
|
|
||
| /** | ||
| * How long a produce takes to be acknowledged. The pending-acks gauge above only | ||
| * separates "stalled" from "not stalled", so it moves once the lane is already | ||
| * holding up offset commits. This shows the lane slowing down while it still | ||
| * works, which is what gates widening the fork onto a lane other teams share. | ||
| */ | ||
| export const flagEvaluationsAckDuration = new Histogram({ | ||
| name: 'ingestion_flag_evaluations_ack_duration_seconds', | ||
| help: 'Time from queueing a flag_evaluations produce to the broker acknowledging it', | ||
| buckets: [0.01, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, 30], | ||
| }) | ||
|
|
||
| export const flagEvaluationsSetPropsTotal = new Counter({ | ||
| name: 'ingestion_flag_evaluations_set_props_total', | ||
| help: '$feature_flag_called events carrying $set/$set_once, which a dedicated flag lane bypassing person processing would lose', | ||
|
|
@@ -106,6 +118,7 @@ export function createForkFlagEvaluationsStep<T extends ForkFlagEvaluationsStepI | |
| }) | ||
| const ack = outputs.queueMessages(FLAG_EVALUATIONS_OUTPUT, messages) | ||
| flagEvaluationsPendingAcks.inc(messages.length) | ||
| const stopAckTimer = flagEvaluationsAckDuration.startTimer() | ||
|
posthog[bot] marked this conversation as resolved.
Resolved
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Timer is started after const stopAckTimer = flagEvaluationsAckDuration.startTimer()
const ack = outputs.queueMessages(FLAG_EVALUATIONS_OUTPUT, messages)
flagEvaluationsPendingAcks.inc(messages.length)Spotted by Graphite |
||
| // Count on the ack, not the enqueue, so a failed produce is not reported as | ||
| // dual-written. | ||
| // | ||
|
|
@@ -116,6 +129,10 @@ export function createForkFlagEvaluationsStep<T extends ForkFlagEvaluationsStepI | |
| const settled = ack.then( | ||
| () => { | ||
| flagEvaluationsPendingAcks.dec(messages.length) | ||
| // Observe latency only on a real ack. A failed produce, especially a | ||
| // local reject like MessageSizeTooLarge, settles before any broker | ||
| // round trip, so timing it would pull the ack-latency signal down. | ||
| stopAckTimer() | ||
| flagEvaluationsEventsTotal.labels('dual_written').inc(messages.length) | ||
| }, | ||
| (error: unknown) => { | ||
|
|
||
| Original file line number | Diff line number | Diff line change | ||||
|---|---|---|---|---|---|---|
| @@ -0,0 +1,322 @@ | ||||||
| from dataclasses import dataclass | ||||||
| from datetime import UTC, date, datetime, timedelta | ||||||
|
|
||||||
| import dagster | ||||||
| import pydantic | ||||||
| import dagster_slack | ||||||
| from clickhouse_driver import Client | ||||||
|
|
||||||
| from posthog import settings | ||||||
| from posthog.clickhouse.cluster import ClickhouseCluster | ||||||
| from posthog.dags.common import JobOwners, settings_with_log_comment, skip_if_already_running | ||||||
| from posthog.models.flag_evaluations.sql import FLAG_EVALUATIONS_SOURCE_EVENT, FLAG_EVALUATIONS_TABLE | ||||||
|
|
||||||
| FLAG_EVALUATIONS_SLACK_CHANNEL = "#alerts-ingestion" | ||||||
|
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. The Slack channel is hardcoded as FLAG_EVALUATIONS_SLACK_CHANNEL = "#alerts-feature-flags"
Suggested change
Spotted by Graphite |
||||||
|
|
||||||
| JOB_NAME = "flag_evaluations_parity" | ||||||
|
|
||||||
|
|
||||||
| class FlagEvaluationsParityConfig(dagster.Config): | ||||||
| """Configuration for the flag_evaluations parity check.""" | ||||||
|
|
||||||
| enabled_team_lookback_days: int = pydantic.Field( | ||||||
| default=7, | ||||||
| description=( | ||||||
| "How far back to look for teams with flag_evaluations rows. A team enabled at any " | ||||||
| "point in this window is checked, so a day where the fork wrote nothing at all " | ||||||
| "reads as a total deficit rather than as the team not being enabled." | ||||||
| ), | ||||||
| ) | ||||||
| teams_per_query: int = pydantic.Field( | ||||||
| default=20, | ||||||
| description=( | ||||||
| "Teams compared per query. The comparison groups by uuid, so its memory scales with " | ||||||
| "the rows in the batch, not with the team count. Lower this if a batch containing a " | ||||||
| "high-volume team runs out of memory." | ||||||
| ), | ||||||
| ) | ||||||
| max_teams: int = pydantic.Field( | ||||||
| default=500, | ||||||
| description=( | ||||||
| "Cap on teams checked in one run, highest volume first. Reaching it is reported, " | ||||||
| "never silent, because a truncated run otherwise reads as full coverage." | ||||||
| ), | ||||||
| ) | ||||||
| target_day: str | None = pydantic.Field( | ||||||
| default=None, | ||||||
| description=( | ||||||
| "Day to check as YYYY-MM-DD. Defaults to yesterday (UTC). Set it on a manual run to " | ||||||
| "re-check the day a past alert named." | ||||||
| ), | ||||||
| ) | ||||||
|
|
||||||
|
|
||||||
| @dataclass(frozen=True) | ||||||
| class TeamParity: | ||||||
| team_id: int | ||||||
| only_in_events: int | ||||||
| only_in_flag_evaluations: int | ||||||
| in_both: int | ||||||
|
|
||||||
|
|
||||||
| @dataclass(frozen=True) | ||||||
| class ParityResults: | ||||||
| day: date | ||||||
| checked: list[TeamParity] | ||||||
| teams_enabled: int | ||||||
| teams_truncated: int | ||||||
|
|
||||||
|
|
||||||
| def _target_day() -> date: | ||||||
| return (datetime.now(tz=UTC) - timedelta(days=1)).date() | ||||||
|
|
||||||
|
posthog[bot] marked this conversation as resolved.
Resolved
|
||||||
|
|
||||||
| def _resolve_target_day(target_day: str | None) -> date: | ||||||
| """The day to check: an explicit YYYY-MM-DD override, else yesterday (UTC).""" | ||||||
| return date.fromisoformat(target_day) if target_day else _target_day() | ||||||
|
|
||||||
|
|
||||||
| @dagster.op | ||||||
| def measure_flag_evaluations_parity( | ||||||
| context: dagster.OpExecutionContext, | ||||||
| config: FlagEvaluationsParityConfig, | ||||||
| cluster: dagster.ResourceParam[ClickhouseCluster], | ||||||
| ) -> ParityResults: | ||||||
| """Compare flag_evaluations against events for every team the fork is writing for. | ||||||
|
|
||||||
| The produce-side counters answer "did we hand the row to Kafka", which is not the | ||||||
| question. Everything past the ack -- the Kafka engine table, the MV, the writable | ||||||
| Distributed, the shard -- is unobserved, and kafka_flag_evaluations sets | ||||||
| kafka_skip_broken_messages, so a malformed row is discarded after a successful produce. | ||||||
| Only comparing the two tables catches that. | ||||||
| """ | ||||||
|
|
||||||
| day = _resolve_target_day(config.target_day) | ||||||
|
|
||||||
| def run_queries(client: Client) -> ParityResults: | ||||||
| query_settings = settings_with_log_comment(context) | ||||||
|
|
||||||
| # The enabled set comes from the data rather than from a mirror of the charts | ||||||
| # allowlist, so the two cannot drift. | ||||||
| enabled_rows = client.execute( | ||||||
| f""" | ||||||
| SELECT team_id, count() AS rows, min(toDate(timestamp)) AS first_day | ||||||
| FROM {settings.CLICKHOUSE_DATABASE}.{FLAG_EVALUATIONS_TABLE} | ||||||
| WHERE toDate(timestamp) >= %(lookback_start)s AND toDate(timestamp) <= %(day)s | ||||||
| GROUP BY team_id | ||||||
| ORDER BY rows DESC | ||||||
| """, | ||||||
| {"lookback_start": day - timedelta(days=config.enabled_team_lookback_days), "day": day}, | ||||||
| settings=query_settings, | ||||||
| ) | ||||||
|
|
||||||
| # A team whose earliest row in the lookback window falls on the checked day was | ||||||
| # switched on that day. Its events from before the allowlist reached the pods have | ||||||
| # no fork row, so comparing it would report a deficit for a fork that works. Skip it; | ||||||
| # its first full day is checked on the next run. | ||||||
| ranked_teams = [int(row[0]) for row in enabled_rows if row[2] < day] | ||||||
| skipped_activation = len(enabled_rows) - len(ranked_teams) | ||||||
| teams = ranked_teams[: config.max_teams] | ||||||
| truncated = len(ranked_teams) - len(teams) | ||||||
|
posthog[bot] marked this conversation as resolved.
Resolved
|
||||||
| context.log.info( | ||||||
| f"{len(ranked_teams)} teams enabled, checking {len(teams)} for {day}" | ||||||
| + (f", skipped {skipped_activation} activated that day" if skipped_activation else "") | ||||||
| ) | ||||||
|
|
||||||
| # The shared cluster resource disables both ceilings (max_execution_time and | ||||||
| # max_memory_usage are "0"), so this comparison must cap itself: it runs on the | ||||||
| # cluster that serves customer queries and its group-by state grows with the | ||||||
| # $feature_flag_called uuids of the largest teams for a whole day. A per-query memory | ||||||
| # breach reports "for query", which the retry policy leaves alone -- unlike a total | ||||||
| # server breach or a socket timeout, which it retries up to 8 times -- so a heavy | ||||||
| # batch fails once instead of repeating at full cost. distributed_aggregation_memory_efficient | ||||||
| # streams each shard's (team_id, uuid) states rather than merging them all in the | ||||||
| # initiator. The ceilings are generous guardrails for a batch of teams_per_query | ||||||
| # teams; lower teams_per_query if a batch reaches them. | ||||||
| comparison_settings = { | ||||||
| **query_settings, | ||||||
| "max_execution_time": "600", | ||||||
| "max_memory_usage": str(100 * 1024**3), | ||||||
| "distributed_aggregation_memory_efficient": "1", | ||||||
| } | ||||||
|
|
||||||
| checked: list[TeamParity] = [] | ||||||
| for start in range(0, len(teams), config.teams_per_query): | ||||||
| batch = teams[start : start + config.teams_per_query] | ||||||
| rows = client.execute( | ||||||
| f""" | ||||||
| SELECT | ||||||
| team_id, | ||||||
| countIf(in_ev > 0 AND in_fe = 0) AS only_in_events, | ||||||
| countIf(in_fe > 0 AND in_ev = 0) AS only_in_flag_evaluations, | ||||||
| countIf(in_fe > 0 AND in_ev > 0) AS in_both | ||||||
| FROM ( | ||||||
| SELECT team_id, uuid, max(is_fe) AS in_fe, max(is_ev) AS in_ev | ||||||
| FROM ( | ||||||
| SELECT team_id, uuid, 1 AS is_fe, 0 AS is_ev | ||||||
| FROM {settings.CLICKHOUSE_DATABASE}.{FLAG_EVALUATIONS_TABLE} | ||||||
| WHERE team_id IN %(teams)s AND toDate(timestamp) = %(day)s | ||||||
|
|
||||||
| UNION ALL | ||||||
|
|
||||||
| SELECT team_id, uuid, 0 AS is_fe, 1 AS is_ev | ||||||
| FROM {settings.CLICKHOUSE_DATABASE}.events | ||||||
| WHERE team_id IN %(teams)s AND toDate(timestamp) = %(day)s | ||||||
| AND event = %(event)s | ||||||
|
posthog[bot] marked this conversation as resolved.
Resolved
posthog[bot] marked this conversation as resolved.
Resolved
posthog[bot] marked this conversation as resolved.
Resolved
Comment on lines
+162
to
+165
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Exclude events from lanes that never run the forkWhy we think it's a valid issue
Issue description
Suggested fixCarry a fork-eligible or ingestion-lane marker into events and filter on it. Alternatively, compare against a source that only real-time lanes produce. Prompt to fix with AI (copy-paste)
Contributor
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. This is a real false-alert path, but I have not changed code because the fix needs a signal that does not exist in queryable form today — a human has to decide how to source it. Confirmed: the fork only runs on real-time lanes (main, overflow, turbo, team2), while delayed lanes (historical, async) never fork. The parity query's events side counts every $feature_flag_called row for the day regardless of lane, so a delayed-lane event lands in only_in_events. With no deficit threshold, a low but steady rate of late events that get rerouted to the historical lane produces a recurring false deficit that can name a team whose fork is working — the exact noise the excess rule was written to avoid. Why it needs a human: the ingestion lane is a consumer/env concept (INGESTION_LANE), not a property on the event. The events table has no lane column — only historical_migration, which flags explicit >=48h batch imports, not the age-rerouted historical-lane events in the reachable window here. So closing this cleanly means either (a) carrying a fork-eligible / ingestion-lane marker onto events and filtering on it (a change across Node ingestion, the events schema/materialization, and this query), or (b) comparing against a source only real-time lanes produce. Both are design changes, not an edit to this file. I considered and rejected an in-file approximation by event age (inserted_at vs timestamp): the rerouting threshold and enablement live in deployment config not readable here, the async lane's routing isn't defined in this repo, and an age filter could wrongly drop a genuinely-late real-time event that was forked — hiding a real deficit, which is worse for a loss monitor than the false positive it fixes. This shares a root cause with the separately-raised enablement-source finding: the job has no queryable view of what the fork actually processed, only the table it writes to and the raw events. A decision on that shared source would resolve both. |
||||||
| -- The fork writes a row only when $feature_flag is a non-empty string, | ||||||
| -- and lets every other $feature_flag_called event continue to the events | ||||||
| -- table untouched. Without the same condition here, each one reads as a | ||||||
| -- lost row. JSONExtractString on its own is not that condition, because | ||||||
| -- it renders a number, boolean, object or array as its text, so | ||||||
| -- JSONType has to reject those types before the empty-string check. | ||||||
| AND JSONType(properties, '$feature_flag') = 'String' | ||||||
| AND JSONExtractString(properties, '$feature_flag') != '' | ||||||
| ) | ||||||
| GROUP BY team_id, uuid | ||||||
| ) | ||||||
| GROUP BY team_id | ||||||
| """, | ||||||
| {"teams": batch, "day": day, "event": FLAG_EVALUATIONS_SOURCE_EVENT}, | ||||||
| settings=comparison_settings, | ||||||
| ) | ||||||
| checked.extend( | ||||||
| TeamParity( | ||||||
| team_id=int(row[0]), | ||||||
| only_in_events=int(row[1]), | ||||||
| only_in_flag_evaluations=int(row[2]), | ||||||
| in_both=int(row[3]), | ||||||
| ) | ||||||
| for row in rows | ||||||
| ) | ||||||
|
|
||||||
| return ParityResults( | ||||||
| day=day, | ||||||
| checked=checked, | ||||||
| teams_enabled=len(ranked_teams), | ||||||
| teams_truncated=truncated, | ||||||
|
posthog[bot] marked this conversation as resolved.
Resolved
|
||||||
| ) | ||||||
|
|
||||||
| return cluster.any_host(run_queries).result() | ||||||
|
|
||||||
|
|
||||||
| def parity_alert_lines(results: ParityResults) -> list[str] | None: | ||||||
| """The Slack message for a run, or None when there is nothing to say. | ||||||
|
|
||||||
| Only a deficit and an uncovered team are worth waking someone for. Excess is reported as | ||||||
| context but never triggers the alert on its own. It counts uuids the fork wrote that the | ||||||
| events table has no row for. Over the week to 2026-08-31 in prod-US it stayed at or below | ||||||
| 0.09 percent of the uuids the fork wrote, and was zero on four of the seven days. Re-sent | ||||||
| uuids are not what it counts: the comparison groups by (team_id, uuid), so the duplicate | ||||||
| rows that flag_evaluations keeps and the ReplacingMergeTree behind events collapses fold | ||||||
| into one entry per side before anything is counted, and a re-sent uuid that reached both | ||||||
| tables lands in in_both. | ||||||
|
|
||||||
| There is no threshold on the deficit for the opposite reason: it has measured zero on | ||||||
| every day checked so far, so any non-zero value is a regression a threshold would hide. | ||||||
| """ | ||||||
|
|
||||||
| # No enabled team means the fork wrote nothing anywhere for the whole lookback window, which | ||||||
| # a rolled-back allowlist produces. Staying quiet here would report it as a clean run. | ||||||
| if not results.teams_enabled: | ||||||
| return [ | ||||||
| f"*flag_evaluations parity* for `{results.day}`", | ||||||
| "No team wrote a flag_evaluations row in the lookback window, so nothing was compared.", | ||||||
| ] | ||||||
|
|
||||||
| deficits = sorted( | ||||||
| (team for team in results.checked if team.only_in_events > 0), | ||||||
| key=lambda team: team.only_in_events, | ||||||
| reverse=True, | ||||||
| ) | ||||||
| if not deficits and not results.teams_truncated: | ||||||
| return None | ||||||
|
|
||||||
| # A team the query covered but that had no rows on the day emits no result row, so | ||||||
| # len(checked) counts only teams with rows. Report the queried count so this does not | ||||||
| # understate coverage or contradict the truncation line below. | ||||||
| queried = results.teams_enabled - results.teams_truncated | ||||||
| excess_total = sum(team.only_in_flag_evaluations for team in results.checked) | ||||||
| lines = [ | ||||||
| f"*flag_evaluations parity* for `{results.day}`", | ||||||
| f"Checked {queried} of {results.teams_enabled} enabled teams " | ||||||
| f"({len(results.checked)} had rows on the day). Excess rows: {excess_total:,}.", | ||||||
| ] | ||||||
| if results.teams_truncated: | ||||||
| lines.append(f"{results.teams_truncated} enabled teams were not checked; raise `max_teams`.") | ||||||
| lines.extend( | ||||||
| f"Team `{team.team_id}`: {team.only_in_events:,} rows in events with no flag_evaluations row" | ||||||
| for team in deficits[:10] | ||||||
| ) | ||||||
| if len(deficits) > 10: | ||||||
| lines.append(f"…and {len(deficits) - 10} more teams with a deficit") | ||||||
| return lines | ||||||
|
|
||||||
|
|
||||||
| @dagster.op | ||||||
| def report_flag_evaluations_parity( | ||||||
| context: dagster.OpExecutionContext, | ||||||
| results: ParityResults, | ||||||
| slack: dagster.ResourceParam[dagster_slack.SlackResource], | ||||||
| ) -> None: | ||||||
| """Post the parity result to Slack when it needs attention.""" | ||||||
|
|
||||||
| context.add_output_metadata( | ||||||
| { | ||||||
| "day": str(results.day), | ||||||
| "teams_checked": results.teams_enabled - results.teams_truncated, | ||||||
| "teams_with_rows": len(results.checked), | ||||||
| "teams_enabled": results.teams_enabled, | ||||||
| "deficit_rows": sum(team.only_in_events for team in results.checked), | ||||||
| "excess_rows": sum(team.only_in_flag_evaluations for team in results.checked), | ||||||
| } | ||||||
| ) | ||||||
|
|
||||||
| lines = parity_alert_lines(results) | ||||||
| if lines is None: | ||||||
| context.log.info(f"Parity holds for {len(results.checked)} teams on {results.day}") | ||||||
| return | ||||||
|
|
||||||
| # A Slack failure is logged and swallowed below, and the per-team deficit lines exist | ||||||
| # nowhere else, so record them before the post is attempted. | ||||||
| context.log.warning("\n".join(lines)) | ||||||
|
|
||||||
| if not settings.CLOUD_DEPLOYMENT: | ||||||
| context.log.info("Skipping Slack notification in non-prod environment") | ||||||
| return | ||||||
|
|
||||||
| # Both regions post to the same channel and team ids are per-region, so the alert | ||||||
| # must name the deployment that lost the rows. | ||||||
| lines.append(f"Environment: {settings.CLOUD_DEPLOYMENT}") | ||||||
|
|
||||||
| # text is the notification and accessibility fallback, and what Slack shows if it rejects | ||||||
| # the rich blocks. It carries the same lines, so the truncation clause survives that reject. | ||||||
| message = "\n".join(lines) | ||||||
| try: | ||||||
| slack.get_client().chat_postMessage( | ||||||
| channel=FLAG_EVALUATIONS_SLACK_CHANNEL, | ||||||
| text=message, | ||||||
| blocks=[{"type": "section", "text": {"type": "mrkdwn", "text": message}}], | ||||||
| ) | ||||||
|
posthog[bot] marked this conversation as resolved.
Resolved
|
||||||
| except Exception as e: | ||||||
| context.log.exception(f"Failed to send Slack notification: {e}") | ||||||
|
|
||||||
|
|
||||||
| @dagster.job(tags={"owner": JobOwners.TEAM_INGESTION.value}) | ||||||
| def flag_evaluations_parity(): | ||||||
| """Check that every row the flag-evaluations fork wrote also reached the events table.""" | ||||||
| report_flag_evaluations_parity(measure_flag_evaluations_parity()) | ||||||
|
|
||||||
|
|
||||||
| @dagster.schedule( | ||||||
| job=flag_evaluations_parity, | ||||||
| # After the previous UTC day is complete and its merges have settled. | ||||||
| cron_schedule="0 4 * * *", | ||||||
| execution_timezone="UTC", | ||||||
| name="flag_evaluations_parity_schedule", | ||||||
| ) | ||||||
| @skip_if_already_running | ||||||
| def flag_evaluations_parity_schedule(context: dagster.ScheduleEvaluationContext) -> dagster.RunRequest: | ||||||
| # Skip while a previous run is still active so catch-up ticks after an outage do not run | ||||||
| # several comparisons at once against the shared events cluster and post duplicate alerts | ||||||
| # for the same day. | ||||||
| return dagster.RunRequest() | ||||||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This needs the author to decide — I haven't changed code or the PR description. The code and the PR description genuinely disagree, and both look deliberate:
ingestion_flag_evaluations_ack_duration_seconds(it isn't on master) with a docstring that justifies it as the signal that 'gates widening the fork onto a lane other teams share.'ingestion_outputs_latency_seconds/kafka_producer_produce_latency_secondsalready time queue-to-ack for this output and topic with finer buckets, and that 'the ingestion path is not touched.'Both can't be the final intent. The decision:
One dependency to note: earlier in this review pass I made this histogram observe only on a successful ack (so a failed produce no longer skews the ack-latency signal). If you choose option 2, that change goes away with the metric; if option 1, it stays. I'd suggest deciding the intent first, since it determines whether the fork step should carry any bespoke ack-latency metric at all.