Skip to content

fix(handler): group captured log messages by call site, not message content#164

Draft
cat-ph wants to merge 2 commits into
mainfrom
fix/log-message-exception-type
Draft

fix(handler): group captured log messages by call site, not message content#164
cat-ph wants to merge 2 commits into
mainfrom
fix/log-message-exception-type

Conversation

@cat-ph

@cat-ph cat-ph commented Jul 9, 2026

Copy link
Copy Markdown
Contributor

💡 Motivation and Context

Exception events built from plain log messages (capture_level captures without a crash_reason) currently use the formatted message as the exception type. Log messages routinely interpolate dynamic values — ids, URLs, inspected terms — so every distinct message produces a distinct type. Error tracking fingerprints the exception type verbatim, which means a single Logger.error("Failed to crawl #{url}") call site creates a separate issue per event instead of one issue for the call site. In production data this makes captured-log exception events group dramatically worse than crash-derived ones: the large majority of such events end up with a unique fingerprint, and server-side masking can't help because the volatile parts are often plain words (URLs, entity names), not just numbers.

This PR keys the type on the logging call site instead: Logger error (MyApp.Crawler.update_stats/2), derived from the mfa log metadata (the same metadata #152 uses for the synthetic stacktrace frame). The full message is still sent in value, so nothing is lost from the issue description or event detail. When mfa metadata is absent (e.g. Logger.bare_log/3), behavior is unchanged.

The crash-reporter entry of chained exceptions (a log message with an attached crash_reason) intentionally keeps its message-derived type: that entry names the issue, and for e.g. Bandit/Cowboy request crashes the banner (** (RuntimeError) oops) is a much better issue title than the logging call site inside the HTTP server would be. The marker that gates this never leaves the handler.

💚 How did you test it?

  • Updated the handler tests that asserted message-derived types, plus a new regression test asserting that two differently-interpolated messages from the same call site produce the same type while keeping distinct values.
  • mix test (316 passed), mix format, mix credo --strict (no new findings).

📝 Checklist

  • I reviewed the submitted code.
  • I added tests to verify the changes.
  • I updated the docs if needed.
  • No breaking change or entry added to the changelog.

If releasing new changes

  • Ran sampo add to generate a changeset file

🤖 Agent context

Autonomy: Human-driven (agent-assisted)

  • Claude Code session: investigated production grouping quality for elixir exception events, read the error tracking fingerprinting pipeline, and traced the unique-fingerprint explosion to message-derived exception types on stackless log captures (frames and chain order were ruled out as causes).
  • Considered and rejected: masking volatile tokens server-side only (interpolated words survive masking), client-side $exception_fingerprint (bypasses server grouping rules), and applying the call-site type to crash-reporter chain entries (would regress issue titles for request crashes).
  • Note for reviewers: this changes the emitted type for message captures, so existing issues for such events will re-key once — those groups are the ones currently splitting per event, so the practical cost is nil.

@cat-ph cat-ph self-assigned this Jul 9, 2026
@cat-ph cat-ph requested a review from hpouillot July 9, 2026 19:42
@github-actions

github-actions Bot commented Jul 9, 2026

Copy link
Copy Markdown
Contributor

posthog-elixir Compliance Report

Date: 2026-07-09 19:59:27 UTC
Duration: 117695ms

✅ All Tests Passed!

46/46 tests passed


Capture Tests

29/29 tests passed

View Details
Test Status Duration
Format Validation.Event Has Required Fields 609ms
Format Validation.Event Has Uuid 611ms
Format Validation.Event Has Lib Properties 611ms
Format Validation.Distinct Id Is String 610ms
Format Validation.Token Is Present 611ms
Format Validation.Custom Properties Preserved 610ms
Format Validation.Event Has Timestamp 610ms
Retry Behavior.Retries On 503 5615ms
Retry Behavior.Does Not Retry On 400 2613ms
Retry Behavior.Does Not Retry On 401 2613ms
Retry Behavior.Respects Retry After Header 5616ms
Retry Behavior.Implements Backoff 15626ms
Retry Behavior.Retries On 500 5615ms
Retry Behavior.Retries On 502 5616ms
Retry Behavior.Retries On 504 5615ms
Retry Behavior.Max Retries Respected 15627ms
Deduplication.Generates Unique Uuids 626ms
Deduplication.Preserves Uuid On Retry 5614ms
Deduplication.Preserves Uuid And Timestamp On Retry 10621ms
Deduplication.Preserves Uuid And Timestamp On Batch Retry 5618ms
Deduplication.No Duplicate Events In Batch 615ms
Deduplication.Different Events Have Different Uuids 613ms
Compression.Sends Gzip When Enabled 611ms
Batch Format.Uses Proper Batch Structure 610ms
Batch Format.Flush With No Events Sends Nothing 607ms
Batch Format.Multiple Events Batched Together 615ms
Error Handling.Does Not Retry On 403 2613ms
Error Handling.Does Not Retry On 413 2612ms
Error Handling.Retries On 408 5615ms

Feature_Flags Tests

17/17 tests passed

View Details
Test Status Duration
Request Payload.Request With Person Properties Device Id 610ms
Request Payload.Flags Request Uses V2 Query Param 610ms
Request Payload.Flags Request Hits Flags Path Not Decide 610ms
Request Payload.Flags Request Omits Authorization Header 609ms
Request Payload.Token In Flags Body Matches Init 610ms
Request Payload.Groups Round Trip 610ms
Request Payload.Groups Default To Empty Object 610ms
Request Payload.Disable Geoip False Propagates As Geoip Disable False 610ms
Request Payload.Disable Geoip Omitted Defaults To False 610ms
Request Payload.Flag Keys To Evaluate Contains Only Requested Key 611ms
Request Lifecycle.No Flags Request On Init Alone 5ms
Request Lifecycle.No Flags Request On Normal Capture 609ms
Request Lifecycle.Two Flag Calls Produce Two Remote Requests 1216ms
Request Lifecycle.Mock Response Value Is Returned To Caller 610ms
Retry Behavior.Retries Flags On 502 914ms
Retry Behavior.Retries Flags On 504 913ms
Side Effect Events.Get Feature Flag Captures Feature Flag Called Event 1212ms

@martosaur

Copy link
Copy Markdown
Contributor

That's an interesting topic! To my knowledge, there's no clear cut solution to tracking log messages which can potentially contain dynamic values. It's always a bit of a trade off between undergrouping and overgrouping.

Using call site for fingerprinting will work great for very broad messages like Logger.error("Unexpected response: #{inspect(response)}"). But for messages with lower cardinality it may lead to overgrouping: Logger.error("Unexpected response with code #{response.status_code}", response: response).

Initially I decided against using call site for fingerprinting because I though undergrouping is easier to addres:

  1. Merge option is readily available in the PostHog UI.
  2. Users have control over their log messages and if they experience undergrouping they can move dynamic values into metadata.

My understanding is that overgrouping would be much harder to address:

  1. There is no easy way to split errors that were already grouped together (or maybe i just don't know about it). And there is a very good chance users won't even notice that an issue is actually multiple issues.
  2. As a user you can't write your log message in a way that would prevent overgrouping. In the example above, it makes sense to not group Unexpected response with code 400 and Unexpected response with code 503 together, but as a user I am forced to move them to different lines to workaround SDK.

WDYT?

@cat-ph

cat-ph commented Jul 9, 2026

Copy link
Copy Markdown
Contributor Author

thanks for looking @martosaur! yeah, I think it's a bit tricky because we've seen (recently at least) a lot of inspect(..) errors that resulted in something like 80% unique fingerprints (undergrouping), which is pretty huge 😞

I was thinking Logger <level> (<Module.function/arity>) might be enough to kinda prevent the overgrouping but was looking for feedback (why I opened it draft haha). you have a good point re: grouping 400 vs 503 together just because they're thrown in the same place hmm 🤔

I wonder if defexception UnexpectedResponseError + Logger.error(msg, crash_reason: {exception, stacktrace}) would be a good/better solution for this case, doesn't look particularly simpler than just logging the error.

there's also the idea of having a log_grouping: :call_site | :message config and defaulting to :call_site to prevent this, but I don't think that's too great either

@martosaur

Copy link
Copy Markdown
Contributor

oooh, if you have access to the aggregate data, is there a way to check if those unique fingerprints have any large clusters? The thing is, most people I know learn fairly quickly to not interpolate dynamic values in logs, but there is a couple of very popular libraries that are guilty of that. For example I would expect DBConnectionError to be one extremely common source of undergrouped issues. If we see that a handful of libraries are responsible for a big chunk of such messages, I could go and potentially fix that in libraries (as I slowly do anyway)

@hpouillot

Copy link
Copy Markdown
Contributor

I think we should avoid putting the message on the exception type, imo the grouping decision should be handled server side and behavior between SDKs should be aligned. If users want to control grouping on the SDK they can still rely on the $exception_fingerprint property. The default behavior should not create 1 issue per exception when you have dynamic data inside your logs. This situation is really hard to manage even with a merge feature as you could end up easily with 10k issues with one occurence.

I also agree that overgrouping should be avoided, we released a new fingerprint algorithm that better take the exception value into account (and strip dynamic fields) when there is no stacktrace. It's not bullet proof but that should help as the message is the only thing we can use to split two error inside a single function.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants