diff --git a/JOURNAL.md b/JOURNAL.md new file mode 100644 index 000000000..8275a643e --- /dev/null +++ b/JOURNAL.md @@ -0,0 +1,110 @@ +## Week 7 — Issue selection + +**Issue link:** (https://github.com/ascherj/pathreview/issues/66) + +**Issue title:** Safety monitoring doesn't emit metrics when the content filter is bypassed by a multi-turn conversation + + +**Tier:** [ ] Tier 1 [ ] Tier 2 [x] Tier 3 + +**Problem summary:** + +Issue number 66 talks about dealing with flaged conversation as a whole, and not one prmopt. It asks us to create SafetyMonitor.get_event_count tool that goes along the conversation and collect the flagged words and see if it should kick the user or the materils that is being requested is safe. + +One way to solve it as I can see is to implement window_hours currently, which means it is getting all the events rather than within the last 1 hour. + +The codebase shows a hardcoded review with no AI generation integrated even and the clear solution is adding the safety monitor and providing multi-turn support. + +**Branch name:** fix/66-safety-monitor-multi-turn-metrics +https://github.com/aliabbaka/pathreview/blob/fix/66-safety-monitor-multi-turn-metrics/JOURNAL.md +**Setup confirmation:** [x] App runs locally at localhost:5173 + +**Cohort ledger:** [x] Issue added to cohort ledger + + +## Week 8 — Reproduction & solution planning + +**Reproduction commit link:** https://github.com/aliabbaka/pathreview/commit/3e041c75750ed1bcc1236005ed38f7c139b4ad7a + +**Reproduction summary:**Added a failing unit test (test_monitoring.py::test_window_hours_is_ignored_reproduces_66) that records 5 lifetime content_filtered events with only 2 inside the last hour, then calls get_event_count("content_filtered", window_hours=1). It returns 5 instead of 2 (assert 5 == 2 fails), confirming window_hours is ignored so events across a multi-turn conversation are never counted within a rolling window. +**PLAN.md link:** https://github.com/aliabbaka/pathreview/blob/fix/66-safety-monitor-multi-turn-metrics/PLAN.md + +**Walkthrough video (recommended):** https://drive.google.com/file/d/1S-X-YzFoySNWFty719cXwbFFI_7OrP8A/view?usp=sharing +**Blockers or open questions:** +If there could be a bigger time frame, more than two hours but that will not increase the latency of the answers. + + +## Week 9 — Implementation & review (mid-week) + +**Fix commit link:** https://github.com/aliabbaka/pathreview/commit/02bd06f + +**What I built:** Switched `SafetyMonitor` from a cumulative `INCR` counter to a +Redis sorted set of timestamped events. `get_event_count` now enforces `window_hours` +via `zremrangebyscore` + `zcard`, mirroring `RateLimiter`. The reproduction test +(`test_window_hours_is_ignored_reproduces_66`) now passes; added 3 tests (timestamped +write, windowed count, error path) and hardened the unknown-type test. `ruff`/`black`/ +`mypy` clean on changed files; 5/5 monitoring tests pass. + +**Draft PR:** https://github.com/ascherj/pathreview/pull/1022 + +**Blockers or open questions:** Whether wiring `get_event_count` into the content-filter +path (PLAN §3.3) should be part of this issue or a separate follow-up. `SafetyMonitor` +currently has no callers. + + +## Week 10 — Iteration & reflection + +### Reviewer feedback + +**Feedback received:** [ ] Yes [x] No — still awaiting review + +**Summary of feedback:** +No peer review has come in yet. PR #1022 is open as a draft and posted for review; I'll +update this section with the reviewer's comments once they land, then flip the PR from +Draft to "Ready for review" after addressing them. + +**How you responded:** +No feedback yet, so no changes made in response. Pending review. + +--- + +### Reflection + +**What was harder than you expected?** +Two things I didn't see coming. First, the repo is seeded with dozens of intentional +bugs, so running `make test-unit` showed 56 failures — it looked like I'd broken +everything, and it took a moment to realize almost all of those belonged to other +issues, not mine. Learning to run just `tests/unit/test_monitoring.py` and judge my work +by *that* was the real skill. Second, Git hygiene tripped me up: a stray full copy of the +project had been cloned inside itself (`pathreview/pathreview/`) which blocked commits, +and at one point my fix and tests got bundled into a single commit mislabeled `test(...)` +instead of a proper `fix(...): Fixes #66`. Cleaning that up mattered more than I expected. + +**What did you learn about working in a large codebase?** +Scope discipline is everything. In my own project I can change anything; here the right +instinct is to touch only my module, match the conventions already in the code, and not +"fix" things outside my issue. The cleanest part of my fix was that I didn't invent a new +approach — I copied the rolling-window sorted-set pattern already used in +`rate_limiter.py`, so `monitoring.py` now reads like the code around it. I also learned to +separate *my* test failures from the pre-existing ones instead of panicking at a red suite. + +**How did AI tools help — and where did they fall short?** +AI was strongest at navigation and drafting: mapping where the bug lived, pointing me at +the `RateLimiter` pattern to mirror, and drafting the Conventional Commit messages, PR +body, and these journal entries. It fell short on anything outside the code — it couldn't +open the PR or run the Slack review (the `gh` CLI wasn't even installed), and the genuinely +judgment-based calls were mine: deciding that wiring `SafetyMonitor` into the content +filter (PLAN §3.3) should be a follow-up rather than scope-creep in this PR. + +**What would you do differently if you started over?** +Commit in small, correctly-labeled steps from the very beginning instead of having to +`reset --soft` and re-split later. I'd also clean up the environment (the nested duplicate +repo) before starting, and decide the scope boundary (§3.3 in or out) up front in PLAN.md +so it didn't stay an open question all the way to the PR. + +**What are you most proud of from this module?** +The reproduction-first workflow. I wrote a failing test that pinned the exact bug — +`window_hours` being ignored so a 1-hour and a 1000-hour window returned the same count — +before touching the implementation, then watched it flip from red to green once the fix +landed. Seeing that single assertion go from `5 == 2` failing to passing made the whole +fix feel provable rather than hopeful. \ No newline at end of file diff --git a/PLAN.md b/PLAN.md new file mode 100644 index 000000000..292626715 --- /dev/null +++ b/PLAN.md @@ -0,0 +1,95 @@ +# PLAN — Issue #66: Safety monitoring doesn't emit windowed metrics across multi-turn conversations + +**Issue:** https://github.com/ascherj/pathreview/issues/66 +**Branch:** `fix/66-safety-monitor-multi-turn-metrics` + +## 1. Problem + +`SafetyMonitor` ([safety/monitoring.py](safety/monitoring.py)) records safety +events (e.g. `content_filtered`, `injection_attempt`) so the system can react +when a user trips safety limits repeatedly. In a multi-turn conversation a user +can bypass the per-message content filter by spreading a harmful request across +several turns — each message looks benign on its own, but the pattern across a +short window is not. + +Detecting that pattern requires asking *"how many safety events occurred in the +last N hours?"*. The current code cannot answer that question: + +1. **No per-event timestamps.** `log_event` stores a single cumulative counter + (`INCR safety:events:{type}`) with a key-level 24h expiry. There is no record + of *when* each event happened. +2. **`window_hours` is a no-op.** `get_event_count(event_type, window_hours=1)` + accepts the argument but ignores it (docstring: *"not enforced here"*) and + returns the lifetime total via a single `GET`. + +Result: a 1-hour window and a 1000-hour window return the same number, so a +multi-turn bypass is never reflected in a time-windowed metric. + +## 2. Reproduction + +Test: [tests/unit/test_monitoring.py](tests/unit/test_monitoring.py) :: +`test_window_hours_is_ignored_reproduces_66`. + +It records that 5 events exist all-time but only 2 within the last hour, then +calls `get_event_count("content_filtered", window_hours=1)` and asserts the +result is `2`. Against the current implementation it returns `5` and the test +fails — that failure is the reproduction. + +``` +AssertionError: window_hours ignored: got 5 (all-time total) instead of 2 ... +assert 5 == 2 +``` + +## 3. Proposed fix + +Adopt the same rolling-window pattern already used by +[safety/rate_limiter.py](safety/rate_limiter.py), which stores timestamped +entries in a Redis **sorted set** (`ZADD` / `ZREMRANGEBYSCORE` / `ZCARD`). + +### 3.1 `log_event` — store timestamped events +- Continue validating `event_type` against `VALID_EVENT_TYPES`. +- Instead of (or in addition to) `INCR`, add the event to a sorted set keyed by + event type, scored by the current UNIX timestamp: + `ZADD safety:events:{event_type} {now: now}`. +- Set a key expiry generous enough to cover the largest window we query + (e.g. 24h), so the set self-trims. +- Keep the existing structlog line and the broad `try/except` so logging failures + never break the request path. + +### 3.2 `get_event_count` — enforce the window +- Compute `window_start = now - window_hours * 3600`. +- Trim expired entries: `ZREMRANGEBYSCORE key 0 window_start`. +- Return the count inside the window: `ZCARD key`. +- Preserve the existing behaviour on error (log + return `0`). + +### 3.3 (Optional, if in scope) surface the metric +Grep shows `SafetyMonitor` currently has no callers. If wiring is in scope, call +`log_event(...)` where the content filter / prompt-defense layers flag input, and +expose `get_event_count(..., window_hours=1)` so the agent can react (e.g. warn or +block) when the windowed count crosses a threshold. If out of scope for #66, note +it as follow-up. + +## 4. Testing + +- The reproduction test flips from failing to passing once `get_event_count` + reads the windowed sorted-set count. +- Add coverage for: + - `log_event` calls `zadd` with a timestamp score and sets an expiry. + - `log_event` still rejects unknown event types (already covered). + - `get_event_count` calls `zremrangebyscore` with the correct `window_start` + and returns `zcard`. + - Error path returns `0`. +- Run: `make test-unit` (or `.venv/bin/pytest tests/unit/test_monitoring.py -v`). + +## 5. Risks / considerations + +- **Data-model change:** counts recorded under the old `INCR` key won't carry + over. Acceptable — safety metrics are ephemeral (24h expiry) and dev-only. +- **Memory:** a sorted set is larger than one integer, but bounded by the expiry + window and event volume; the rate limiter already accepts this trade-off. +- **Clock source:** use a single `now` per call, mirroring `rate_limiter.py`. + +## 6. Out of scope + +- Redesigning the content filter's detection patterns. +- Persisting safety events beyond the rolling window (no long-term audit store). diff --git a/docs/SETUP.md b/docs/SETUP.md index 32fbaa294..e5db9d5ee 100644 --- a/docs/SETUP.md +++ b/docs/SETUP.md @@ -38,7 +38,7 @@ Install Docker Engine and the Docker Compose plugin (not the standalone `docker- ```bash # 1. Clone your fork -git clone https://github.com//pathreview.git +git clone https://github.com/aliabbaka/pathreview.git cd pathreview git remote add upstream https://github.com/jamjamgobambam/pathreview.git diff --git a/frontend/package-lock.json b/frontend/package-lock.json index 7efac84d9..12b1f52e2 100644 --- a/frontend/package-lock.json +++ b/frontend/package-lock.json @@ -99,7 +99,6 @@ "integrity": "sha512-CGOfOJqWjg2qW/Mb6zNsDm+u5vFQ8DxXfbM09z69p5Z6+mE1ikP2jUXw+j42Pf1XTYED2Rni5f95npYeuwMDQA==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "@babel/code-frame": "^7.29.0", "@babel/generator": "^7.29.0", @@ -449,7 +448,6 @@ } ], "license": "MIT", - "peer": true, "engines": { "node": ">=18" }, @@ -473,7 +471,6 @@ } ], "license": "MIT", - "peer": true, "engines": { "node": ">=18" } @@ -1561,7 +1558,6 @@ "integrity": "sha512-jp2P3tQMSxWugkCUKLRPVUpGaL5MVFwF8RDuSRztfwgN1wmqJeMSbKlnEtQqU8UrhTmzEmZdu2I6v2dpp7XIxw==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "undici-types": "~7.18.0" } @@ -1579,7 +1575,6 @@ "integrity": "sha512-z9VXpC7MWrhfWipitjNdgCauoMLRdIILQsAEV+ZesIzBq/oUlxk0m3ApZuMFCXdnS4U7KrI+l3WRUEGQ8K1QKw==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "@types/prop-types": "*", "csstype": "^3.2.2" @@ -1972,7 +1967,6 @@ } ], "license": "MIT", - "peer": true, "dependencies": { "baseline-browser-mapping": "^2.9.0", "caniuse-lite": "^1.0.30001759", @@ -3507,7 +3501,6 @@ "integrity": "sha512-L88oL7D/8ufIES+Zjz7v0aes+oBMh2Xnh3ygWvL0OaICOomKEPKuPnIfBJekiXr+BHbbMjrWn/xqrDQuxFTeyA==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "@asamuzakjp/dom-selector": "^2.0.1", "cssstyle": "^4.0.1", @@ -4094,7 +4087,6 @@ "resolved": "https://registry.npmjs.org/react/-/react-18.3.1.tgz", "integrity": "sha512-wS+hAgJShR0KhEvPJArfuPVN1+Hz1t0Y6n5jLrGQbkb4urgPE/0Rve+1kMB1v/oWgHgm4WIcV+i7F2pTVj+2iQ==", "license": "MIT", - "peer": true, "dependencies": { "loose-envify": "^1.1.0" }, @@ -4107,7 +4099,6 @@ "resolved": "https://registry.npmjs.org/react-dom/-/react-dom-18.3.1.tgz", "integrity": "sha512-5m4nQKp+rZRb09LNH59GM4BxTh9251/ylbKIbpe7TpGxfJ+9kv6BLkLBXIjjspbgbnIBNqlI23tRnTWT0snUIw==", "license": "MIT", - "peer": true, "dependencies": { "loose-envify": "^1.1.0", "scheduler": "^0.23.2" @@ -4771,7 +4762,6 @@ "integrity": "sha512-o5a9xKjbtuhY6Bi5S3+HvbRERmouabWbyUcpXXUA1u+GNUKoROi9byOJ8M0nHbHYHkYICiMlqxkg1KkYmm25Sw==", "dev": true, "license": "MIT", - "peer": true, "dependencies": { "esbuild": "^0.21.3", "postcss": "^8.4.43", diff --git a/safety/monitoring.py b/safety/monitoring.py index a12ece9f3..6cf6b81e0 100644 --- a/safety/monitoring.py +++ b/safety/monitoring.py @@ -1,8 +1,9 @@ """Safety event monitoring.""" +import time + import redis import structlog -from datetime import datetime, timedelta logger = structlog.get_logger() @@ -16,7 +17,7 @@ class SafetyMonitor: "injection_attempt", "content_filtered", "bias_detected", - "rate_limited" + "rate_limited", } def __init__(self, redis_client: redis.Redis): @@ -30,6 +31,11 @@ def __init__(self, redis_client: redis.Redis): def log_event(self, event_type: str, details: dict) -> None: """Log a safety event. + Each event is stored as a timestamped member in a Redis sorted set so + that counts can be computed over a rolling time window (mirroring + ``RateLimiter``). This lets multi-turn conversations that trip the + content filter across several turns be counted within a window. + Args: event_type: Type of event (from VALID_EVENT_TYPES) details: Event details dict @@ -38,36 +44,38 @@ def log_event(self, event_type: str, details: dict) -> None: logger.warning("unknown_event_type", event_type=event_type) return - timestamp = datetime.utcnow().isoformat() - try: # Log to structlog logger.warning("safety_event", event_type=event_type, **details) - # Store count in Redis for monitoring + # Store a timestamped entry in a sorted set for windowed counting. key = f"safety:events:{event_type}" - self.redis.incr(key) - # Set expiry to 24 hours + now = time.time() + self.redis.zadd(key, {str(now): now}) + # Expiry covers the largest window we query; the set self-trims. self.redis.expire(key, 86400) except Exception as e: logger.error("safety_monitor_error", error=str(e)) def get_event_count(self, event_type: str, window_hours: int = 1) -> int: - """Get count of safety events. + """Get count of safety events within a rolling window. Args: event_type: Type of event - window_hours: Time window in hours (not enforced here; for reference) + window_hours: Rolling time window in hours Returns: - Count of events in the window + Count of events recorded within the last ``window_hours`` hours. """ key = f"safety:events:{event_type}" + now = time.time() + window_start = now - window_hours * 3600 try: - count = self.redis.get(key) - return int(count) if count else 0 + # Drop events older than the window, then count what remains. + self.redis.zremrangebyscore(key, 0, window_start) + return self.redis.zcard(key) except Exception as e: logger.error("event_count_error", event_type=event_type, error=str(e)) diff --git a/tests/unit/test_monitoring.py b/tests/unit/test_monitoring.py new file mode 100644 index 000000000..63e4e043e --- /dev/null +++ b/tests/unit/test_monitoring.py @@ -0,0 +1,112 @@ +"""Tests for safety/monitoring.py + +Reproduction for issue #66: "Safety monitoring doesn't emit metrics when the +content filter is bypassed by a multi-turn conversation." + +Root cause +---------- +`SafetyMonitor.log_event` stores a single cumulative counter per event type +(`INCR safety:events:{type}`) with a key-level 24h expiry. Because individual +events carry no timestamps, `SafetyMonitor.get_event_count(window_hours=...)` +cannot compute a rolling-window count. The `window_hours` argument is accepted +but ignored (its own docstring says "not enforced here"), so any multi-turn / +time-window detection silently returns the all-time total instead of the count +within the requested window. + +The `test_window_hours_is_ignored_reproduces_66` test below documents the +CORRECT (post-fix) expectation and therefore FAILS against the current +implementation — that failure is the reproduction of the bug. +""" + +from unittest.mock import Mock + +import pytest + +from safety.monitoring import SafetyMonitor + + +@pytest.mark.unit +class TestSafetyMonitor: + """Test suite for SafetyMonitor.""" + + @pytest.fixture + def mock_redis(self) -> Mock: + """Create a mock Redis client.""" + return Mock() + + @pytest.fixture + def monitor(self, mock_redis: Mock) -> SafetyMonitor: + """Create a SafetyMonitor instance with mocked Redis.""" + return SafetyMonitor(mock_redis) + + def test_log_event_rejects_unknown_type(self, monitor: SafetyMonitor, mock_redis: Mock) -> None: + """Unknown event types are ignored and never written to Redis.""" + monitor.log_event("not_a_real_event", {"foo": "bar"}) + mock_redis.incr.assert_not_called() + mock_redis.zadd.assert_not_called() + + def test_log_event_writes_timestamped_entry( + self, monitor: SafetyMonitor, mock_redis: Mock + ) -> None: + """log_event stores a sorted-set entry scored by timestamp + sets expiry.""" + monitor.log_event("content_filtered", {"reason": "test"}) + + mock_redis.zadd.assert_called_once() + key, mapping = mock_redis.zadd.call_args[0] + assert key == "safety:events:content_filtered" + # Single member whose value equals its score (the timestamp). + ((member, score),) = mapping.items() + assert float(member) == score + mock_redis.expire.assert_called_once_with("safety:events:content_filtered", 86400) + + def test_get_event_count_trims_then_counts_window( + self, monitor: SafetyMonitor, mock_redis: Mock + ) -> None: + """get_event_count trims by window_start and returns the sorted-set size.""" + mock_redis.zcard = Mock(return_value=3) + + count = monitor.get_event_count("content_filtered", window_hours=2) + + mock_redis.zremrangebyscore.assert_called_once() + key, low, high = mock_redis.zremrangebyscore.call_args[0] + assert key == "safety:events:content_filtered" + assert low == 0 + assert high > 0 # window_start = now - 2h, a timestamp in the past + assert count == 3 + + def test_get_event_count_returns_zero_on_error( + self, monitor: SafetyMonitor, mock_redis: Mock + ) -> None: + """A Redis failure is swallowed and yields 0 (fail-closed count).""" + mock_redis.zremrangebyscore = Mock(side_effect=Exception("redis down")) + assert monitor.get_event_count("content_filtered") == 0 + + def test_window_hours_is_ignored_reproduces_66( + self, monitor: SafetyMonitor, mock_redis: Mock + ) -> None: + """REPRODUCTION (#66): get_event_count ignores window_hours. + + Scenario: over the lifetime of the key, 5 ``content_filtered`` events + have been recorded, but only 2 of them occurred within the last hour + (a multi-turn conversation slowly tripping the filter). + + A correct, window-aware implementation must return **2** for + ``window_hours=1``. The current implementation stores only a lifetime + counter, so it returns **5** — proving the window is not enforced. + + We mock both access patterns so this test is agnostic to the fix: + - ``get`` -> current (buggy) lifetime-counter model returns 5 + - ``zcard`` -> a sorted-set, window-aware model returns 2 + """ + # Lifetime total the current implementation reads via GET. + mock_redis.get = Mock(return_value=b"5") + # Count within the 1-hour window a windowed implementation would read. + mock_redis.zcard = Mock(return_value=2) + + count = monitor.get_event_count("content_filtered", window_hours=1) + + assert count == 2, ( + f"window_hours ignored: got {count} (all-time total) instead of 2 " + "(events within the last hour). A multi-turn bypass that trips the " + "filter across turns is not reflected in a windowed metric." + )