Tickets :: [#5369] horde not cleaning up memcache session locks properly

6.0.0-alpha12

6/8/25

Summary	horde not cleaning up memcache session locks properly
Queue	Horde Base
Queue Version	3.1.4
Type	Bug
State	Resolved
Priority	1. Low
Owners
Requester	webadmin (at) ualberta (dot) ca
Created	05/16/2007 (6598 days ago)
Due
Updated	05/21/2007 (6593 days ago)
Assigned	05/17/2007 (6597 days ago)
Resolved	05/21/2007 (6593 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

05/21/2007 03:08:12 PM	Michael Slusarz	Comment #5 State ⇒ Resolved	Reply to this comment
The memcache server has been rewritten in HEAD to no longer use the filesystem for locking. So this bug seems not to be relevant anymore - or you could say it has been fixed as the problem as described should no longer occur (of course this change may cause problems elsewhere, but that should be the subject of other tickets).

05/17/2007 10:31:02 PM	Chuck Hagenbuch	Comment #4	Reply to this comment
Especially with multiple memcache servers that would seem necessary, yes...

05/17/2007 10:09:09 PM	Jan Schneider	Comment #3	Reply to this comment
By the way, wouldn't it make more sense to create a lock object in the memcache instead of the filesystem? This seems too obvious to me.

05/17/2007 09:03:41 PM	Chuck Hagenbuch	Comment #2 State ⇒ Feedback	Reply to this comment
In terms of the lock, what if you put the unlink lines (like this one) in the _unlockSession function? @unlink($this->_params['lock_dir'] . '/lock_' . $id); (_unlockSession is called on session_close, but the unlink isn't. In every other case that _unlockSession is called, we do the unlink). By the way, the "unknown reason" that the lock is created in the first place is that guests have sessions too. But there isn't a real reason to destroy the guest sessions, and while the memcache data is cleaned up (it's only the lock file that isn't cleaned up - not the actual session), we don't know the session ids that expire so in gc() we can't go cleaning up locks. What I'm proposing is that we don't need the lock file after close() is called; it'll be recreated again when the session is opened, and that might be a performance hit. (though I doubt it - apparently I made that change, and I'm not sure why: http://cvs.horde.org/diff.php?sa=1&r1=1.12&r2=1.13&f=framework%2FSessionHandler%2FSessionHandler%2FAttic%2Fmemcached.php) The other behavior you're seeing looks like an artifact of how PHP handles session_destroy() - but I'm really not sure.

05/17/2007 06:47:34 PM	Chuck Hagenbuch	Summary ⇒ horde not cleaning up memcache session locks properly

05/16/2007 05:42:21 PM	webadmin (at) ualberta (dot) ca	Comment #1 Priority ⇒ 1. Low Type ⇒ Bug Summary ⇒ horde not cleaning up session locks properly Queue ⇒ Horde Base State ⇒ Unconfirmed	Reply to this comment
Previously posted to horde mailing list: Horde: 3.1.4 Imp: H3 (4.1.4) memcached-1.1.12 (openbsd package) PHP 4.4.1 Hi all, I'm still seeing the following in my logs: May 15 11:38:27 dwc1 HORDE[2924]: [imp] Error retrieving session data (id = ba2ae485eabbd2ffa54eaa25ebc18147) [on line 83 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] This is when I log out of horde. So I did a test. I cleared my lock directory (/tmp) and logged in to horde. It wrote the following files: lock_3b11f01b2742a400239e612fdb0bf643 lock_1227f5f5959ec90311eedc7abe56f536 When I log out, lock_3b11f01b2742a400239e612fdb0bf643 is removed from /tmp, but the other one remains. But the error I get is: May 15 11:43:47 dwc1 HORDE[32588]: [imp] Error retrieving session data (id = 3b11f01b2742a400239e612fdb0bf643) [on line 83 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] So... why is it trying to retrieve a session lock file that it's already removed? AND why is it leaving the other one there? After few months or so I have to reboot the machine because /tmp has filled up with zero-length lock files that haven't been cleaned up by horde and I run out of inodes. -------- I did a quick test to see what caused what. I cleared out my session lock directory (/tmp) and opened a fresh browser. I entered the URL for the imp login page and was surprised to see my debug log going before I had even entered a username. So I checked /tmp and sure enough I saw: # ls lock_bf43d8d214bda96441f1c2e7ffc01696 So then I proceeded to log in as usual. Once I had logged in I checked /tmp again..... # ls lock_6c7991152662fd39cc948bdcbf348146 lock_bf43d8d214bda96441f1c2e7ffc01696 Then I immediately logged out. Checking /tmp again gives us: # ls lock_bf43d8d214bda96441f1c2e7ffc01696 SO it appears that for some unknown reason horde is writing a session lock file before a user even logs in and then never ever cleans up after itself. Looking at the debug log before I log in (all that was requested was the login page) I see the following: May 16 11:18:20 dwc1 HORDE[8849]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 HORDE[8849]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 HORDE[8849]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 HORDE[8849]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 HORDE[8849]: [horde] Connected to a memcache server for memcache SessionHandler [on line 195 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 HORDE[8849]: [horde] Read session data (id = bf43d8d214bda96441f1c2e7ffc01696) [on line 89 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 [8849]: [imp] Already connected to a memcache server for memcache SessionHandler [on line 165 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 [8849]: [imp] Wrote session data (id = bf43d8d214bda96441f1c2e7ffc01696) [on line 114 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:18:20 dwc1 root: [8849] 129.128.11.16 - - [16/May/2007:11:18:20 -0600] "GET / HTTP/1.1" 200 4334 Though I don't know why horde would be reading/writing any session info prior to the user actually logging in, even if there's a good reason for it the fact remains that horde is not cleaning up those pre-login sessions. Then on top of that if you watch the logs when you click the logout button you'll see the following: May 16 11:19:41 dwc1 HORDE[2825]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[2825]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[2825]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[2825]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[2825]: [horde] Connected to a memcache server for memcache SessionHandler [on line 195 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[2825]: [horde] Read session data (id = 6c7991152662fd39cc948bdcbf348146) [on line 89 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 \M^P\M-7\M-=\M-O\M^T\M-7\M-=\M-O\^C[2825]: [horde] Already connected to a memcache server for memcache SessionHandler [on line 165 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 \M^P\M-7\M-=\M-O\M^T\M-7\M-=\M-O\^C[2825]: [horde] Wrote session data (id = 6c7991152662fd39cc948bdcbf348146) [on line 114 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 root: [2825] 129.128.11.16 - - [16/May/2007:11:19:41 -0600] "GET /horde/login.php?logout_reason=logout HTTP/1.1" 302 38 May 16 11:19:41 dwc1 HORDE[19752]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [horde] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [horde] Connected to a memcache server for memcache SessionHandler [on line 195 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [horde] Read session data (id = 6c7991152662fd39cc948bdcbf348146) [on line 89 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Logout for testuser [xxx.xxx.xxx.xxx] from {xxx.xxx.xxx.xxx:yyyy} [on line 42 of "/var/www/horde/imp/login.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Already connected to a memcache server for memcache SessionHandler [on line 165 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Deleted session data (id = 6c7991152662fd39cc948bdcbf348146) [on line 138 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Added [xxx.xxx.xxx.xxx:yyyy] as memcache server for memcache SessionHandler [on line 186 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Connected to a memcache server for memcache SessionHandler [on line 195 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Error retrieving session data (id = 6c7991152662fd39cc948bdcbf348146) [on line 83 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Already connected to a memcache server for memcache SessionHandler [on line 165 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 HORDE[19752]: [imp] Wrote session data (id = 6c7991152662fd39cc948bdcbf348146) [on line 114 of "/var/www/horde/lib/Horde/SessionHandler/memcache.php"] May 16 11:19:41 dwc1 root: [19752] xxx.xxx.xxx.xxx - - [16/May/2007:11:19:41 -0600] "GET /login.php?logout_reason=logout HTTP/1.1" 200 4363 So here we see that once the user logs out, their session key is deleted immediately. But then almost immediately Horde tries to read the session it just deleted, producing the "Error retreiving" message. That makes no sense whatsoever.