[Tickets #5369] horde not cleaning up session locks properly
bugs at bugs.horde.org
bugs at bugs.horde.org
Wed May 16 17:42:21 UTC 2007
DO NOT REPLY TO THIS MESSAGE. THIS EMAIL ADDRESS IS NOT MONITORED.
Ticket URL: http://bugs.horde.org/ticket/?id=5369
-----------------------------------------------------------------------
Ticket | 5369
Created By | webadmin at ualberta.ca
Summary | horde not cleaning up session locks properly
Queue | Horde Base
Version | 3.1.4
Type | Bug
State | Unconfirmed
Priority | 1. Low
Owners |
-----------------------------------------------------------------------
webadmin at ualberta.ca (2007-05-16 10:42) wrote:
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.
More information about the bugs
mailing list