Request Logging: Avoid forcing a session store load when resolving the session id for logging (closes #23082)#23083
Conversation
|
Claude finished @AndyButland's task in 3m 1s —— View job PR ReviewTarget: Guards
Suggestions
Approved with Suggestions for improvementGood to go. The fix is correct: skipping |
There was a problem hiding this comment.
Pull request overview
This PR updates AspNetCoreSessionManager.SessionId to avoid forcing an ASP.NET Core session store load during request logging when the incoming request does not carry the session cookie, preventing synchronous IDistributedCache.Get(...) round-trips on anonymous/non-session requests in distributed-session setups.
Changes:
- Guard session-id resolution behind an inbound session-cookie presence check to avoid triggering
Session.Id(and thusDistributedSession.Load()). - Inject
IOptions<SessionOptions>intoAspNetCoreSessionManagerto read the configured session cookie name. - Add unit tests verifying
"0"behavior when sessions aren’t available,nullwhen no session cookie is present (andSession.Idis not read), and normal behavior when the cookie is present.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
| src/Umbraco.Web.Common/AspNetCore/AspNetCoreSessionManager.cs | Avoids session store load by only reading Session.Id when the configured session cookie is present. |
| tests/Umbraco.Tests.UnitTests/Umbraco.Web.Common/AspNetCore/AspNetCoreSessionManagerTests.cs | Adds regression/unit coverage ensuring Session.Id isn’t read when no session cookie is present, plus baseline behaviors. |
|
This resolves the anonymous traffic case well. However, for any user with an established session cookie (logged-in users, anything that writes session), Session.Id still forces the synchronous load per request, just for logging - so on session-heavy traffic the thread pool starvation risk under load returns. Could we log a hash of the cookie value instead of Session.Id so log enrichment never triggers a load at all? If the session id is only there to filter requests to the same session, then a hash of the cookie should give the same amount of info without causing these extra L2 hits. |
…mpatibility but giving options to skip session Id logging or use a cookie hash.
|
Good point @jemayn. I like your approach, but I think if we introduce this in 17 we do need to be careful about retaining the previous behaviour (just in case anyone particularly wants and expects the actual session ID in the logs). To support that I've made session-id log enrichment is configurable rather than a single hard-coded behaviour. New setting
Default behaviour is unchanged; operators running distributed/L2-backed sessions can opt into I'm thinking that for Cloud, when load balancing is enabled, this option could be fixed to Manual testing completed — running the local dev site on the default in-memory session store, two requests per mode with a shared cookie jar,
Also covered by unit tests in |
Description
On a distributed-session setup (the session store backed by an L2 cache via
IDistributedCache— e.g. load-balanced sites or a standalone L2 cache add-on), the request-logging session-id enricher caused a synchronous, blocking L2 cache round-trip on every non-static request, including anonymous renders that never otherwise use session.Root cause
The chain:
AddWebComponents→AddSession).UmbracoRequestLoggingMiddlewarepushesHttpSessionIdEnricherinto the SerilogLogContextfor every non-static request.ISessionIdResolver.SessionId→AspNetCoreSessionManager.SessionId→httpContext.Session.Id.DistributedSession.IdforcesLoad(), which calls the synchronousIDistributedCache.Get(...)— a blocking network round-trip on a thread-pool worker, even when no session data exists.With the in-memory store this is a cheap dictionary lookup and invisible; with a distributed store it blocks worker threads under burst load and contributes to thread-pool starvation and request timeouts.
Fix
AspNetCoreSessionManager.SessionIdnow only readshttpContext.Session.Idwhen the incoming request carries the configured session cookie. An established session always sends its cookie back (ASP.NET Core has no cookieless session mode), so the cookie's absence means there is nothing meaningful to load — and we avoid forcing the blocking store read.Backward compatibility
There is a comment in the code to evaluate if we even need to be enriching the log with the session ID, but given we are, people could be relying on it, so we should maintain the behaviour. The only slight change, which I think is acceptable, is the very first request where the session is established won't have a request cookie and as such the session ID won't be logged.
Testing
Automated
Added a new set of unit tests in
AspNetCoreSessionManagerTeststhat covers this change and existing functionality.Manual testing
Verified end-to-end on the default in-memory session store using a temporary debug controller that establishes a session and logs (so the enricher fires).
Hit the endpoint twice with a shared cookie jar, so the second call sends the
UMB_SESSIONcookie set by the first:Then check
umbraco/Logs/UmbracoTraceLog.*.jsonfor theSession id logging debug request handledentries:{"@t":"...","@mt":"Session id logging debug request handled","RequestPath":"/debug/session-id-logging","Log4NetLevel":"INFO ","HttpRequestId":"4566ed7d-ec83-4d0f-8296-083a8681bd64","HttpRequestNumber":1} {"@t":"...","@mt":"Session id logging debug request handled","RequestPath":"/debug/session-id-logging","Log4NetLevel":"INFO ","HttpRequestId":"7817e5f9-6ffa-4c31-9fca-0d67af7b820d","HttpRequestNumber":2,"HttpSessionId":"bf0e82df-ede2-dbcc-794b-57b5379576d0"}HttpRequestNumber: 1): noHttpSessionIdproperty — anonymous request, no inbound session cookie, store never read.HttpRequestNumber: 2):HttpSessionIdpresent and populated — the session cookie was sent, a real session exists, and the id is logged as before.Stashing the
AspNetCoreSessionManagerchange and re-running makes call 1 log a non-nullHttpSessionIdagain (the old always-read behaviour), confirming the guard is working as expected.