Here's an example of what I'm seeing... (field order is: Pid from Session, Action, Session ID, Date of Action)
Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:42:28 2008 21133 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:42:28 2008 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:42:28 2008 OLD SESSION READ: 38217d32e244768fe63622e1be76fc95 21087 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:42:28 2008 21087 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:03 2008 28179 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:03 2008 28179 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:03 2008 28364 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:04 2008 28364 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:11 2008 28364 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:12 2008 28364 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:12 2008 21132 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:12 2008 21132 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:17 2008 21132 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:18 2008 21132 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:20 2008 21132 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 12:43:21 2008 21133 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 13:20:06 2008 OLD SESSION READ: 38217d32e244768fe63622e1be76fc95 21133 Wed Mar 19 12:42:28 2008 28596 Writing 38217d32e244768fe63622e1be76fc95 Wed Mar 19 13:20:06 2008 21133 Reading 38217d32e244768fe63622e1be76fc95 Wed Mar 19 13:20:06 2008 OLD SESSION READ: 38217d32e244768fe63622e1be76fc95 21133 Wed Mar 19 12:42:28 2008 This is for one session... The first line is where the session was created. It was updated and immediately written. Then it was read. That read failed. The session was written again, and for the next few requests, that data was available from memcached. Finally, at 13:20, the session was read again, and what we got was that original session that we wrote way back at 12:42:28. Sometime between 12:43:21 and 13:20:06, the session we originally wrote got committed to memcached. In the mean time however, the writing process (21133) wrote to, and read from memcached (I have an expanded log), so I know it wasn't hung. I cannot figure out how that could have happened. This is really driving me nuts. I've spent the better part of three days trying to reproduce this behavoir outside of apache, but have yet to succeed. Suggestions are welcome! Rob On Tue, Mar 18, 2008 at 4:56 PM, Robert Landrum <[EMAIL PROTECTED]> wrote: > Maybe this would be better asked on the Apache list... > > I have a single memcache server (1.2.3) for my sessions. Our session > aren't that important, so a database is overkill. > > Our sessions are mostly there to keep track of the user's current status, > such as whether or not they're authenticated and what groups they're in > (cached from the DB). > > What I've discovered, and cannont reproduce outside of apache, is what > appears to be a buffering problem. > > I'm logging all my sessions. Here's a rundown of what's happening. > > 1.) Created New Session and Session Key (c1c23b3b82bc355b2c17d7ae2f99bcac) > 2.) Modified Session tied to c1c23b3b82bc355b2c17d7ae2f99bcac. > 3.) Wrote Session (by way of untie) > 4.) Read Session (c1c23b3b82bc355b2c17d7ae2f99bcac) > !!! Session is not what was written > 5.) Modified Session tied to c1c23b3b82bc355b2c17d7ae2f99bcac > 6.) Wrote Session (by way of untie) > 7.) Read Session (values consistent with step 6 write) > 8.) Wrote Session (by way of untie) > 9.) Read Session (values written on step 3 now appear). > > Basically, I'm somehow pulling out old sessions that have, at least in > theory, been overwritten (in some cases, several times). The time delay > between step 3 and step 9 can be as little as 10 seconds, or as long as 30 > minutes (reportedly; my logging shows 4 minutes max). > > So, I started adding some values to my sessions, like _last_modified_pid > and _last_modified_time, and a few more useful items for debugging. What I > discovered was that the process id writing in step 3 wrote another user's > session just before my read at step 9. To me, that seems like some sort of > buffering issue. Digging into Cache::Memcached, the module used by > Apache::Session::Memcached, I see that the sockets it creates are being set > to autoflush, which means this must be some form of memcached issue. > > Sadly, though, I cannot prove that. Despite several attempts to create a > process that mimics apache session handling, I cannot reproduce the effect > outside of apache. > > Anyone run into this issue? > > Rob > > >
