Description

I run

The MoinMoin site works well for the first access. This is http://127.0.0.1/emnosWiki/ for my local system. Reloading this page works fine. After trying to access a different page I get:

 [Errno 13] Permission denied: 'D:\\data\\DEV\\workspace\\websody\\home\\Moin\\emnosWiki\\data\\cache\\i18n\\__lock__\\write_lock' 

I tried to analyse this problem and ThomasWaldmann helped me. We think the root cause is that the __lock__ folder st_mtime is incorrectly reported using localtime (not UTC timestamp as usual). Thus, the calculated age of the lock yields a negative value (-7200s for a 0s old lock). This happens in util.lock.py.

Running http://localhost/emnosWiki/moin.cgi?action=test produces the attached output (error.log). I changed the isExpired method in util.lock.py: 

   1     def isExpired(self):
   2         """ Return True if too old or missing; False otherwise
   3 
   4         TODO: Since stat returns times using whole seconds, this is
   5         quite broken. Maybe use OS specific calls like Carbon.File on
   6         Mac OS X?
   7         """
   8         if self.timeout is None:
   9             return not self.exists()
  10         try:
  11             lock_age = time.time() - os.stat(self.lockDir).st_mtime
  12             log("%s => UTC=%s, LOCAL=%s => AGE=%s\n" %( self.lockDir, time.ctime( time.time() ), time.ctime(os.stat(self.lockDir).st_mtime), str( lock_age )) )
  13             return lock_age > self.timeout
  14         except OSError, err:
  15             if err.errno == errno.ENOENT:
  16                 # No such lock file, therefore "expired"
  17                 return True
  18             raise

The additional log entry in line 12 produces the following output for the diagnostic page: 

[Sun Apr 30 11:55:31 2006] lock: c:\temp\lock_t7kw8a\lock => UTC=Sun Apr 30 11:55:31 2006, LOCAL=Sun Apr 30 13:55:31 2006 => AGE=-7199.10400009
[Sun Apr 30 11:55:31 2006] lock: c:\temp\lock_t7kw8a\lock => UTC=Sun Apr 30 11:55:31 2006, LOCAL=Sun Apr 30 13:55:31 2006 => AGE=-7199.0940001
[Sun Apr 30 11:55:31 2006] lock: c:\temp\lock_t7kw8a\lock => UTC=Sun Apr 30 11:55:31 2006, LOCAL=Sun Apr 30 13:55:31 2006 => AGE=-7199.08400011
[Sun Apr 30 11:55:31 2006] lock: c:\temp\lock_t7kw8a\lock => UTC=Sun Apr 30 11:55:31 2006, LOCAL=Sun Apr 30 13:55:31 2006 => AGE=-7199.07399988
etc.

Apache runs under SYSTEM, the environment shows TZ=GMT1EDT. The result of time.time() is the value logged as "UTC" (and correct). The timestamp of the lock dir (logged as LOCAL) is incorrect, because timestamps should be UTC (ever!), but this is obviously kind of a "local time" timestamp. Anybody able to reproduce this error?

Steps to reproduce

Please try out the following script with your web server: 

   1 #!python.exe
   2 
   3 import time, os
   4 
   5 print "Content-type: text/html"
   6 print
   7 print "<pre>"
   8 print "time.ctime( time.time ):", time.ctime( time.time() )
   9 print
  10 print "time.asctime(time.localtime()):", time.asctime(time.localtime())
  11 print
  12 print "time.asctime(time.gmtime()):", time.asctime(time.gmtime())
  13 print
  14 print "</pre>"

The result for my system is: 

time.ctime( time.time ): Sun Apr 30 12:12:23 2006
time.asctime(time.localtime()): Sun Apr 30 12:12:23 2006
time.asctime(time.gmtime()): Sun Apr 30 12:12:23 2006

I run this test.py script at 14:12. Local time for the webserver user is wrong!?

Thanks in advance -- MichaelRau 2006-04-30 12:24:28

This script doesn't show a bug, it just shows that it is run within UTC timezone (so there is no difference between utc/gmtime and localtime). The +2h offset between utc timezone and your real localtime is correct. So please give a small script that shows the filesystem st_mtime problem.

Workaround

Moved from MoinMoinQuestions

I carefully followed the instructions in the INSTALL.HTML and I think I have everything correct. AND: the wiki runs. But I can see the following error message with my first site access: 

[Sat Apr 29 19:49:27 2006] page cache failed after creation

And after some minutes I see the following additional error 

[Sat Apr 29 19:53:03 2006] OSError: [Errno 13] Permission denied: 'D:\\data\\DEV\\workspace\\websody\\home\\Moin\\emnosWiki\\data\\cache\\i18n\\__lock__\\write_lock'

The next access trials gives me the following lines in ERROR.LOG 

[Sat Apr 29 20:10:43 2006] Can't acquire read lock in D:\data\DEV\workspace\websody\home\Moin\emnosWiki\data\cache\i18n\__lock__
[Sat Apr 29 20:10:43 2006] UnboundLocalError: local variable 'data' referenced before assignment

I attached my local diagnostic (http://localhost/emnosWiki/moin.cgi?action=test) which FAILED (failures=3, errors=1). See MichaelRau_error.log.

Discussion

I guess the only way to work around such brokenness is to test that stuff on moin startup, set some fs_time_difference value to the observed offset from UTC and use that offset to fix the wrongly reported values. The problem is that this offset is not constant due to DST/non-DST timezones - we already had that problem at another place. For the special case of locks, it should work in most (but not all) cases, though.

Try NOT setting the TZ environment variable. You have set it to TZ=GMT1EDT and windows is obviously confused by that. I reproduced it and it vanished when not having a TZ variable set.

Plan

CategoryMoinMoinNoBug

MoinMoin: MoinMoinBugs/AcquireExclusiveLockFails (last edited 2007-10-29 19:09:21 by localhost)