unexpected "Discarding duplicate repository" warning

[Christian Boos]

I see this pretty regularly in t.e.o's log, right after the morning restart:

[pid 3103 1108724048] 2010-05-21 07:12:48,038 Trac[env] INFO: -------------------------------- environment startup [Trac 0.12dev-r9714] --------------------------------
[pid 3102 1099991376] 2010-05-21 07:12:48,918 Trac[env] INFO: -------------------------------- environment startup [Trac 0.12dev-r9714] --------------------------------
[pid 3103 1108724048] 2010-05-21 07:13:57,230 Trac[env] WARNING: base_url option not set in configuration, generated links may be incorrect
[pid 3102 1578375504] 2010-05-21 07:14:02,407 Trac[env] WARNING: base_url option not set in configuration, generated links may be incorrect
[pid 3102 1133562192] 2010-05-21 07:14:12,937 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3102 1494448464] 2010-05-21 07:14:13,046 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3102 1620339024] 2010-05-21 07:14:13,697 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3102 1477663056] 2010-05-21 07:14:14,531 Trac[main] WARNING: HTTPBadRequest: 400 Bad Request (Missing or invalid form token. Do you have cookies enabled?)
[pid 3102 1158740304] 2010-05-21 07:14:14,559 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3103 1654249808] 2010-05-21 07:14:15,169 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3103 1478003024] 2010-05-21 07:14:15,174 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3102 1569982800] 2010-05-21 07:14:16,348 Trac[main] WARNING: HTTPBadRequest: 400 Bad Request (Missing or invalid form token. Do you have cookies enabled?)
[pid 3103 1201043792] 2010-05-21 07:14:16,488 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3102 1586768208] 2010-05-21 07:14:18,368 Trac[main] WARNING: HTTPBadRequest: 400 Bad Request (Missing or invalid form token. Do you have cookies enabled?)
[pid 3103 1243007312] 2010-05-21 07:14:18,481 Trac[api] WARNING: Discarding duplicate repository ''
[pid 3103 1133902160] 2010-05-21 07:14:18,925 Trac[main] ERROR: Internal Server Error:
...  File "build/bdist.linux-x86_64/egg/trac/db/pool.py", line 120, in get_cnx
    'seconds', time=timeout))
TimeoutError: ...

Ignore the usual TimeoutError error for a second.

We have 2 processes (3103 and 3104) and several threads, the Discarding duplicate repository warning comes from a race condition as all the threads within a same process are trying to initialize the same self._all_repositories dict. We should acquire the self._lock first.

Speaking of that RepositoryManager._lock, it's a Lock, not a RLock, and I wonder… if in RepositoryManager.get_repository's critical section we somehow re-enter the method (I don't see how, though), this would be a clear explanation for the TimeoutError, as that thread will deadlock while getting hold on a db connection. Well, maybe not, as I don't see how the process would recover by itself from such a situation, which it does a few minutes later (last error 07:15:46,956)…

Also interesting is that some of those threads emitting a warning are the same that present a TimeoutError a bit later, for one thread even as soon as 20.2 seconds later.

[Remy Blank]

Instead of locking, how about the following:

trac/versioncontrol/api.py

@@ -566 +566 @@
     def get_all_repositories(self):
         """Return a dictionary of repository information, indexed by name."""
         if not self._all_repositories:
-            self._all_repositories = {}
+            all_repositories = {}
             for provider in self.providers:
                 for reponame, info in provider.get_repositories() or []:
-                    if reponame in self._all_repositories:
+                    if reponame in all_repositories:
                         self.log.warn("Discarding duplicate repository '%s'",
                                       reponame)
                     else:
                         info['name'] = reponame
                         if 'id' not in info:
                             info['id'] = self.get_repository_id(reponame)
-                        self._all_repositories[reponame] = info
+                        all_repositories[reponame] = info
+            self._all_repositories = all_repositories
         return self._all_repositories
 
     def get_real_repositories(self):

There can still be a race at startup between several threads, but all of them will create the same value for self._all_repositories, so it doesn't matter.

[Remy Blank]

Patch applied in [9801].