Rack generates a session_id internally which we like to include in logs
for tracking requests. This session_id wasn't getting picked up by out
log wrapper because of interdependencies in the middleware call stack
and bugs in rack/rails. Read on for details:
See the order of the middleware stack by running: `rake middleware`
The main players in this saga are:
- RequestContextGenerate middleware
- session store middleware:
ActionDispatch::Session::EncryptedCookieStore <
ActionDispatch::Session::CookieStore <
Rack::Session::Cookie <
Rack::Session::Abstract::ID
- Rack::Session::Abstract::SessionHash
How to intercept the session_id:
The Rack session_id is generated lazily the first time the SessionHash
(which is a thin wrapper around a ruby hash) is read from or written to.
This needs to happen after the session has been loaded out of the cookie
by the session store middleware, which happens after our
RequestContextGenerate middleware. We don't just want to move the
generation of the request id later, because then the first couple log
lines will not tagged with a request id.
So our idea was to capture the session_id in an un-encrypted cookie that
could be read early in the middleware call stack (which is fine to be
public, and only used for logs to not a big deal if it's tampered with).
Again, this happens lazily on first access, so our best bet is to catch
it on the way out of the middleware stack. But when
RequestContextGenerator returns it's already too late, because cookies
have already been written to the header. So we introduce a new
middleware that captures the session_id, writes it to a cookie, and then
modify RequestContextGenerator to read from the cookie.
This works great except that with this setup, after a log in attempt the
redirect after login would still be logged with the old "unknown"
session_id and not the new, logged-in session_id. When a session is
cleared (what happens at log in time), ActionDispatch implements
a `reset_session` that we call, which calls session.destroy, but rack
had not implemented session.destroy, so rails patched it, but then after
calling destroy, they reset the session to a plain hash (not
a SessionHash), so an id isn't generated until the plain-hash session is
written to the cookie, which happens AFTER our new middleware finishes
in the stack (and never sets it in the place we look for it).
Rails 4:
Rack internals changed somewhat between rack-1.4 and rack-1.5 and the id
moves from being stored in the session options hash to the main session
hash. We'll need to fix this for rails 4.
A better way:
It may be better to try to keep a handle on the actual SessionHash so
that we can dynamically load the id for log lines, and pick up id
changes immediately as they happen, mid-request. We'd have to make sure
the lookups weren't too expensive though, vs just saving a string.
fixes CNVS-15259
Test plan:
- start a server, make a request
- you should see log lines start with [session_id, request_id] and
session_id should be present, not just "-"
Change-Id: I0289db255b2b0bc3b118e32fc1d0d9381455b1ec
Reviewed-on: https://gerrit.instructure.com/64092
Reviewed-by: Brian Palmer <brianp@instructure.com>
Tested-by: Jenkins
QA-Review: August Thornton <august@instructure.com>
Product-Review: Simon Williams <simon@instructure.com>
5b9497d77a