env.config.save() may destroy trac.ini

[Emmanuel Blot]

Trac:	0.12dev-r8263
Python:	2.5.4 (r254:67916, Feb 17 2009, 20:36:34) [GCC 4.3.3]
setuptools:	0.6c9
psycopg2:	2.0.9
Genshi:	0.6dev-r1052
Babel:	-
mod_wsgi:	2.5
Pygments:	1.0
Bitten:	0.6dev-r0
Subversion:	1.6.4 (r38063)
RPC:	1.0.6
jQuery:	1.3.2

If a plugin (namely: ​CustomFieldAdminPlugin) provides invalid data to the Configuration module, Trac raises an error while updating the configuration file.

The net result is a partially written trac.ini which early terminates right after the last valid processed option.

I know the first culprit is the plugin which should not provide invalid data to Trac, however the issue here is not a recoverable: the trac.ini file is simply destroyed, and it seems Trac does not attempt to keep a backup configuration file.

It would be better and more realiable to:

1. create a new temporary file with the new configuration, then
2. replace the existing configuration file once the new one has been successfully created

2009-09-01 10:33:40,326 Trac[main] ERROR: Internal Server Error: 
Traceback (most recent call last):
  File "/local/engine/trac/trac/web/main.py", line 464, in _dispatch_request
    dispatcher.dispatch(req)
  File "/local/engine/trac/trac/web/main.py", line 212, in dispatch
    resp = chosen_handler.process_request(req)
  File "/local/engine/trac/trac/admin/web_ui.py", line 114, in process_request
    path_info)
  File "build/bdist.linux-i686/egg/customfieldadmin/customfieldadmin.py", line 72, in render_admin_panel
    cfapi.update_custom_field(self.env, cfdict, create=True)
  File "build/bdist.linux-i686/egg/customfieldadmin/api.py", line 99, in update_custom_field
    self.create_custom_field(env, customfield)
  File "build/bdist.linux-i686/egg/customfieldadmin/api.py", line 92, in create_custom_field
    env.config.save()
  File "/local/engine/trac/trac/config.py", line 198, in save
    val.encode('utf-8')))
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 6: ordinal not in range(128)

The error does not end up right here.
Once Trac has self-destroyed its own configuration file, it starts reporting a funny error:

2009-09-01 10:33:45,403 Trac[env] ERROR: Exception caught while checking for upgrade: 
Traceback (most recent call last):
  File "/local/engine/trac/trac/env.py", line 590, in open_environment
    needs_upgrade = env.needs_upgrade()
  File "/local/engine/trac/trac/env.py", line 429, in needs_upgrade
    db = self.get_db_cnx()
  File "/local/engine/trac/trac/env.py", line 275, in get_db_cnx
    return DatabaseManager(self).get_connection()
  File "/local/engine/trac/trac/db/api.py", line 88, in get_connection
    return self._cnx_pool.get_cnx(self.timeout or None)
  File "/local/engine/trac/trac/db/pool.py", line 176, in get_cnx
    return _backend.get_cnx(self._connector, self._kwargs, timeout)
  File "/local/engine/trac/trac/db/pool.py", line 109, in get_cnx
    cnx = connector.get_connection(**kwargs)
  File "/local/engine/trac/trac/db/sqlite_backend.py", line 127, in get_connection
    return SQLiteConnection(path, params, log)
  File "/local/engine/trac/trac/db/sqlite_backend.py", line 173, in __init__
    raise TracError(_('Database "%(path)s" not found.', path=path))
TracError: Database "/local/var/trac/projects/conax/db/trac.db" not found.

I'm not sure how/why Trac wants to find a trac.db file, it is likely that it falls back to SQLite when it cannot find the DB connection string, but the message for the admin is hard to understand: Trac fails to connect to a DB which has never existed, because the connection string does not exist anymore in the configuration file. It would be better to report a missing connection string here.

It seems that this error does not stop Trac from accessing the DB. So the final error is

2009-09-01 10:33:45,489 Trac[main] ERROR: Exception caught while post-processing request: 
Traceback (most recent call last):
  File "/local/engine/trac/trac/web/main.py", line 246, in dispatch
    self._post_process_request(req)
  File "/local/engine/trac/trac/web/main.py", line 332, in _post_process_request
    f.post_process_request(req, *(None,)*extra_arg_count)
  File "build/bdist.linux-i686/egg/revtree/web_ui.py", line 224, in post_process_request
    if req.perm.has_permission('REVTREE_VIEW'):
  File "/local/engine/trac/trac/perm.py", line 526, in has_permission
    return self._has_permission(action, resource)
  File "/local/engine/trac/trac/perm.py", line 540, in _has_permission
    check_permission(action, perm.username, resource, perm)
  File "/local/engine/trac/trac/perm.py", line 427, in check_permission
    perm)
  File "/local/engine/trac/trac/perm.py", line 284, in check_permission
    get_user_permissions(username)
  File "/local/engine/trac/trac/perm.py", line 359, in get_user_permissions
    for perm in self.store.get_user_permissions(username):
  File "/local/engine/trac/trac/perm.py", line 175, in get_user_permissions
    db = self.env.get_db_cnx()
  File "/local/engine/trac/trac/env.py", line 275, in get_db_cnx
    return DatabaseManager(self).get_connection()
  File "/local/engine/trac/trac/db/api.py", line 88, in get_connection
    return self._cnx_pool.get_cnx(self.timeout or None)
  File "/local/engine/trac/trac/db/pool.py", line 176, in get_cnx
    return _backend.get_cnx(self._connector, self._kwargs, timeout)
  File "/local/engine/trac/trac/db/pool.py", line 109, in get_cnx
    cnx = connector.get_connection(**kwargs)
  File "/local/engine/trac/trac/db/sqlite_backend.py", line 127, in get_connection
    return SQLiteConnection(path, params, log)
  File "/local/engine/trac/trac/db/sqlite_backend.py", line 173, in __init__
    raise TracError(_('Database "%(path)s" not found.', path=path))
TracError: Database "/local/var/trac/projects/conax/db/trac.db" not found.
2009-09-01 10:33:45,489 Trac[main] WARNING: HTTPInternalError: 500 Trac Error (Database "/local/var/trac/projects/conax/db/trac.db" not found.)

[Emmanuel Blot]

See ​ticket:8623

[osimons]

Replying to eblot:

See ​ticket:8623

Correct reference should be ​th:ticket:5760. That said, I see no issues with latest plugin using 0.11.6dev and not quite sure what (if anything) may be different in trunk. We'll follow up the plugin-specific details there.

Keeping this ticket open though as safer writing of trac.ini is a good idea, and incomplete ini files can lead to many serious issues when custom configurations are replaced with defaults from options registry - like for instance missing custom security policies.

[Christian Boos]

Now that I think about it, even when the write operation is progressing successfully, nothing prevents Trac to read the partially written trac.ini file either.

We should write the configuration to a temporary file, then rename it to trac.ini.

On Windows, the rename would fail if trac.ini is currently being read, so we could add a retry in this case.

[Emmanuel Blot]

Replying to osimons:

Replying to eblot:

See ​ticket:8623

Correct reference should be ​th:ticket:5760. That said, I see no issues with latest plugin using 0.11.6dev and not quite sure what (if anything) may be different in trunk. We'll follow up the plugin-specific details there.

How do you know which version of the plugin is actually run, as setup.py seems to be out of sync?

Keeping this ticket open though as safer writing of trac.ini is a good idea, and incomplete ini files can lead to many serious issues when custom configurations are replaced with defaults from options registry - like for instance missing custom security policies.

Not mentioning the loss of important data as the trac.ini file may not have been backed up since the latest modifications.

[osimons]

Replying to eblot:

How do you know which version of the plugin is actually run, as setup.py seems to be out of sync?

I'll bump version for you and add information to 'About Trac' just to make sure - see #5710. BTW, you seem to be running the plugin out of a build directory (build/bdist.linux-i686/egg/customfieldadmin/) - that is intentional?

[osimons]

Oops - forget the link to local ticket 5710… Irrelevant of course, and just clumsy fingers when trying to reference ​th:ticket:5760 again getting both link-style and ticket number wrong :-)

[Remy Blank]

Looking into that.

[Remy Blank]

Patch adding atomic config updates.

[Remy Blank]

The patch above updates the config file atomically by writing to a temporary file in the same directory, then renaming over trac.ini. As suggested in comment:3, it retries for two seconds on windows if the rename raises a WindowsError.

Feedback welcome.

[osimons]

Nice. Looks good. And thanks for making the supporting util methods - I needed the same for another file I write as part of my custom Trac setup :-) I'll try to give it a spin and migrate my custom code too. Patch is for 0.11-stable, right?

[Remy Blank]

Replying to osimons:

Patch is for 0.11-stable, right?

Correct.

[osimons]

Looking at the code, I kind of feel the API would be cleaner if we also made a replace_file(filename, data) that abstracted away the temporary file in the same directory + the attributes/perm preservation? Or even changed the current method to create_or_replace_file()?

Also, a question: What is the probability of two threads/processes writing and renaming at the same time? With 2 second delay on Windows, could the situation arise where suddenly both start renaming? Would some sort of locking be needed as well?

[Remy Blank]

Replying to osimons:

Looking at the code, I kind of feel the API would be cleaner if we also made a replace_file(filename, data) that abstracted away the temporary file in the same directory + the attributes/perm preservation?

Interesting. That would require writing the whole file content to a StringIO first, so that it can be passed to replace_file(). Actually, I'm pretty sure that I have seen such a function before. Probably in Mercurial.

Also, a question: What is the probability of two threads/processes writing and renaming at the same time? With 2 second delay on Windows, could the situation arise where suddenly both start renaming? Would some sort of locking be needed as well?

The file update is atomic, so one of the processes is going to win, and the changes from the other one will be lost. While still not quite ideal, it's already much better than a corrupt file. The temporary file will be different for each thread/process, so there's no race condition there. Changes to trac.ini should be relatively rare anyway, and I don't think we can do much better (with reasonable effort).

Looking at the Mercurial code, they have an interesting way of renaming over an open file. They rename the destination file to a temporary, unlink it, then rename the source to the destination. I'll try that as well.

Oh, there it is: atomictempfile. I'll have to understand that first :)

[Christian Boos]

Replying to rblank:

Oh, there it is: atomictempfile. I'll have to understand that first :)

Once you do, please pass on the explanation :-) For me at least (Vista with UAC), that method doesn't work.

[Remy Blank]

A better implementation of atomic file updates. Some parts untested.

[Remy Blank]

The patch above implements a nicer API for atomic file updates, through an AtomicFile object that can be either committed, or rolled back.

The update is atomic on Unix, and tries to be on Windows. It uses one of the following methods to rename the temporary file to the final name, in order of preference:

• MoveFileTransacted(): available since Windows Vista. This rename is specified to be atomic. I haven't been able to test it, though, as I don't have a Vista machine.

• MovefileEx(): not truly atomic, but quite close. Tested on Windows XP.

• os.rename(): not atomic. This is what Mercurial implements, and as noted in comment:14, it doesn't actually work if the file is open. We could add the retry functionality.

The first two options require ctypes. Now I wonder if this added complexity is really worth it, or if we should just keep the third option (with the retry).

Testing of the first option on Vista would be welcome.

[Remy Blank]

Fixed fallback rename when destination doesn't exist.

[Remy Blank]

The patch above is an update to make the fallback rename solution work in the case where the destination file doesn't exist already.

In the current state, the config file update has the following properties:

• On Unix, the update will always succeed and be atomic. If there are concurrent updates, the last one will win and updates from previous ones will be lost. This is unavoidable unless we put the config into the database.

• On Windows Vista and later, with ctypes installed (or Python ≥2.5), the same properties hold.

• On Windows XP and lower, or without ctypes, the rename will not be atomic and may fail, due to concurrent updates or if the config file is open for reading. In the former case, the worst that can happen is that a temporary file could be left in the conf directory. In the latter case, the update will simply fail, and the user will be alerted. Both cases should be rare enough.

All cases are much better than the current solution, where the config file can be corrupted. I wouldn't complicate the logic with retries on Windows, as the config file should only rarely be open (only during an environment reload).

I'm still looking for a volunteer to test the atomic solution on Windows Vista.

[Christian Boos]

Ah… finally! I can stop my digging through the recent tickets :-)

I tested the rename function under Vista sp2 this morning, Python 2.6.1, ctypes 1.1.0. It works, I can rename(src,dst) even when dst is actually opened, impressive!

I had to change:

MoveFileTransacted = ctypes.kernel32.MoveFileTransactedA 

to:

MoveFileTransacted = ctypes.windll.kernel32.MoveFileTransactedA 

Also, the following:

                      if not MoveFileTransacted(src, dst, None, None, 
                          MOVEFILE_REPLACE_EXISTING 
                          | MOVEFILE_WRITE_THROUGH, ta): 
                                raise ctypes.WinError() 
                            if not CommitTransaction(ta): 
                                raise ctypes.WinError() 

could be rewritten:

                      if MoveFileTransacted(src, dst, None, None, 
                          MOVEFILE_REPLACE_EXISTING 
                          | MOVEFILE_WRITE_THROUGH, ta) and \
                         CommitTransaction(ta): 
                          return
                      raise ctypes.WinError() 

[Remy Blank]

Thanks for testing! Patch (with improvements) applied in [8635].

[osimons]

Thanks - works great! Also when reused for my custom management plugin :-)

[Remy Blank]

Testing on Vista has shown that the variant with MoveFileTransacted() can actually rename an open file, so the corresponding unit test has been set to run in that case in [8655].

[Mikael Relbe]

Using WinXP Pro and Trac 0.11.6, I get exception ctype.WinError() when the ​trachacks:AccountManagerPlugin operates on the svnserve password store. For more info, please see ​trachacks:ticket:6356.

I would suspect the problem belongs to Trac, and not the plugin…

[Mikael Relbe <mikael@…>]

Milestone 0.11.6 does not seem reasonable… clearing it to allow this ticket to be triaged (I am new here, please correct me if I am doing something bad).

[Remy Blank]

Could you please post the whole traceback, including the error message?

[Mikael Relbe]

Replying to rblank:

Could you please post the whole traceback, including the error message?

Python traceback:

2009-12-21 17:21:05,733 Trac[main] DEBUG: Dispatching <Request "POST u'/admin/accounts/users'">
2009-12-21 17:21:05,765 Trac[session] DEBUG: Retrieving session for ID u'Mikael'
2009-12-21 17:21:05,780 Trac[main] ERROR: Internal Server Error: 
Traceback (most recent call last):
  File "C:\Python26\lib\site-packages\trac-0.11.6-py2.6.egg\trac\web\main.py", line 450, in _dispatch_request
    dispatcher.dispatch(req)
  File "C:\Python26\lib\site-packages\trac-0.11.6-py2.6.egg\trac\web\main.py", line 206, in dispatch
    resp = chosen_handler.process_request(req)
  File "C:\Python26\lib\site-packages\trac-0.11.6-py2.6.egg\trac\admin\web_ui.py", line 114, in process_request
    path_info)
  File "build\bdist.win32\egg\acct_mgr\admin.py", line 117, in render_admin_panel
    return self._do_users(req)
  File "build\bdist.win32\egg\acct_mgr\admin.py", line 185, in _do_users
    _create_user(req, self.env, check_permissions=False)
  File "build\bdist.win32\egg\acct_mgr\web_ui.py", line 71, in _create_user
    mgr.set_password(user, password)
  File "build\bdist.win32\egg\acct_mgr\api.py", line 128, in set_password
    if store.set_password(user, password):
  File "build\bdist.win32\egg\acct_mgr\svnserve.py", line 60, in set_password
    cfg.save()
  File "C:\Python26\lib\site-packages\trac-0.11.6-py2.6.egg\trac\config.py", line 225, in save
    fileobj.close()
  File "C:\Python26\lib\site-packages\trac-0.11.6-py2.6.egg\trac\util\__init__.py", line 178, in commit
    rename(self._temp, self._path)
  File "C:\Python26\lib\site-packages\trac-0.11.6-py2.6.egg\trac\util\__init__.py", line 120, in rename
    raise ctypes.WinError()
WindowsError: (2, 'Det g\xe5r inte att hitta filen.')
2009-12-21 17:21:05,842 Trac[chrome] DEBUG: Prepare chrome data for request

The WindowsError message states "File not found" (in Swedish).

System Information::

User Agent	Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.2b5) Gecko/20091204 Firefox/3.6b5 (.NET CLR 3.5.30729)
Trac	0.11.6 r8866
Python	2.6.4 (r264:75708, Oct 26 2009, 08:23:19) [MSC v.1500 32 bit (Intel)]
setuptools	0.6c11
SQLite	3.5.9
pysqlite	2.4.1
Genshi	0.6dev-r1092
Pygments	1.1.1
Subversion	1.6.6 (r40053)
jQuery	1.2.6
​AccountManagerPlugin	0.11 ​r7163

Hope this is to some help for tracking the problem.

[Mikael Relbe]

Replying to mrelbe:

Python traceback: …

Sorry, forgot to mention what caused the error: I simply tried to add a new user using the AccountManagerPlugin which is setup to use svn's password file. When that file is to be updated by config.py of Trac, the exception occurs as stated above.

(I am a total newbie to Python, I am not capable to elaborate further on this…)

[Remy Blank]

I should re-check this before 0.12.

[mrelbe <mikael@…>]

Replying to rblank:

I should re-check this before 0.12.

Thank you! Please also check ​trachacks:ticket:6356#comment:2 (and please ignore comment 3 :)

Merry Christmas!

[Remy Blank]

It seems that MoveFileEx() is failing, which can be the case if the destination file is open. But I don't understand how it could fail with "File not found" (which I assume means that the source file cannot be found). And even worse, how replacing MoveFileEx() with os.remove() + os.rename() can solve the issue.

[Remy Blank]

This is related to #8913, and both should be fixed for 0.11.7.

[Remy Blank]

The issue with ​th:AccountManagerPlugin was due to its using Unicode paths, which were not supported. This has been fixed in [8994] by using the wide Windows API for renaming.