Edgewall Software
Modify ↓

Opened 16 years ago

Closed 16 years ago

#8270 closed defect (fixed)

Cache subsystem issue when a new page is created

Reported by: Emmanuel Blot Owned by: Remy Blank
Priority: normal Milestone: 0.12
Component: wiki system Version: 0.12dev
Severity: major Keywords: cache
Cc: Branch:
Release Notes:
API Changes:
Internal Changes:

Description

See ​http://groups.google.com/group/trac-dev/browse_thread/thread/ebe3a0f20e63c278 for initial report

How to reproduce

It has been quite easy to reproduce the original issue:

I've set the project log to "debug" level, but I don't see any useful information.
Once the log level has been modified:

  1. Reload Apache2 configuration (/etc/init.d/apache2 reload)
  2. Open the WikiStart page in a browser window
  3. Type TestBug within the quick jump search window
  4. Be offered to create this new page (TestBug page did not exist prior to this test)
  5. Submit the new page
  6. Select "Index" wiki page link
  7. TestBug page appears
  8. Reload the browser windows content
  9. TestBug page does not appear

Trac configuration

Trac:	0.12dev-r8176
Python:	2.5.4 (r254:67916, Feb 17 2009, 20:16:45) [GCC 4.3.3]
setuptools:	0.6c9
SQLite:	3.6.13
pysqlite:	2.5.0
Genshi:	0.6dev-r1052
Babel:	-
Pygments:	1.0
jQuery:	1.3.2

As requested in the above discussion thread: Trac server runs multiple projects (10 Trac projects), and use mod_fastcgi.

Log file

2009-05-07 16:18:30,813 Trac[loader] DEBUG: Adding plugin TracRevtreeLogEnhancer 0.2.0dev-r4024 from /local/var/trac/plugins/TracRevtreeLogEnhancer-0.2.0dev_r4024-py2.5.egg
2009-05-07 16:18:30,814 Trac[loader] DEBUG: Adding plugin TracCustomFieldAdmin 0.2 from /local/var/trac/plugins/TracCustomFieldAdmin-0.2-py2.5.egg
2009-05-07 16:18:30,814 Trac[loader] DEBUG: Adding plugin TracGrowlPlugin 0.2.1dev-r3950 from /local/var/trac/plugins/TracGrowlPlugin-0.2.1dev_r3950-py2.5.egg
2009-05-07 16:18:30,814 Trac[loader] DEBUG: Adding plugin Bitten 0.6dev-r629 from /local/engine/bitten
2009-05-07 16:18:30,814 Trac[loader] DEBUG: Adding plugin Genshi 0.6dev-r1052 from /local/engine/genshi-trunk
2009-05-07 16:18:30,814 Trac[loader] DEBUG: Adding plugin setuptools 0.6c9 from /usr/lib/python2.5/site-packages
2009-05-07 16:18:30,814 Trac[loader] DEBUG: Adding plugin TracRevtreePlugin 0.6.4dev-r5601 from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:30,815 Trac[loader] DEBUG: Adding plugin Trac 0.12dev-r8176 from /local/engine/trac-trunk
2009-05-07 16:18:30,815 Trac[loader] DEBUG: Loading trac.ticket.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:30,815 Trac[loader] DEBUG: Loading trac.mimeview.php from /local/engine/trac-trunk
2009-05-07 16:18:30,815 Trac[loader] DEBUG: Loading trac.ticket.query from /local/engine/trac-trunk
2009-05-07 16:18:30,816 Trac[loader] DEBUG: Loading trac.attachment from /local/engine/trac-trunk
2009-05-07 16:18:30,816 Trac[loader] DEBUG: Loading trac.versioncontrol.svn_fs from /local/engine/trac-trunk
2009-05-07 16:18:30,816 Trac[loader] DEBUG: Loading trac.mimeview.patch from /local/engine/trac-trunk
2009-05-07 16:18:30,816 Trac[loader] DEBUG: Loading trac.mimeview.txtl from /local/engine/trac-trunk
2009-05-07 16:18:30,821 Trac[loader] DEBUG: Skipping "trac.mimeview.txtl = trac.mimeview.txtl [textile]": ("DistributionNotFound: textile>=2.0" not found)
2009-05-07 16:18:30,821 Trac[loader] DEBUG: Loading trac.admin.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:30,822 Trac[loader] DEBUG: Loading trac.ticket.admin from /local/engine/trac-trunk
2009-05-07 16:18:30,822 Trac[loader] DEBUG: Loading trac.mimeview.rst from /local/engine/trac-trunk
2009-05-07 16:18:30,822 Trac[loader] DEBUG: Loading trac.db.postgres from /local/engine/trac-trunk
2009-05-07 16:18:30,822 Trac[loader] DEBUG: Loading trac.versioncontrol.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:30,822 Trac[loader] DEBUG: Loading trac.timeline from /local/engine/trac-trunk
2009-05-07 16:18:30,823 Trac[loader] DEBUG: Loading trac.mimeview.pygments from /local/engine/trac-trunk
2009-05-07 16:18:30,823 Trac[loader] DEBUG: Loading trac.wiki.admin from /local/engine/trac-trunk
2009-05-07 16:18:30,823 Trac[loader] DEBUG: Loading trac.about from /local/engine/trac-trunk
2009-05-07 16:18:30,823 Trac[loader] DEBUG: Loading trac.wiki.interwiki from /local/engine/trac-trunk
2009-05-07 16:18:30,824 Trac[loader] DEBUG: Loading trac.ticket.roadmap from /local/engine/trac-trunk
2009-05-07 16:18:30,824 Trac[loader] DEBUG: Loading trac.mimeview.silvercity from /local/engine/trac-trunk
2009-05-07 16:18:30,829 Trac[loader] DEBUG: Skipping "trac.mimeview.silvercity = trac.mimeview.silvercity [silvercity]": ("DistributionNotFound: SilverCity>=0.9.4" not found)
2009-05-07 16:18:30,829 Trac[loader] DEBUG: Loading trac.wiki.macros from /local/engine/trac-trunk
2009-05-07 16:18:30,829 Trac[loader] DEBUG: Loading trac.db.sqlite from /local/engine/trac-trunk
2009-05-07 16:18:30,829 Trac[loader] DEBUG: Loading trac.wiki.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:30,830 Trac[loader] DEBUG: Loading trac.mimeview.enscript from /local/engine/trac-trunk
2009-05-07 16:18:30,830 Trac[loader] DEBUG: Loading trac.web.auth from /local/engine/trac-trunk
2009-05-07 16:18:30,830 Trac[loader] DEBUG: Loading trac.admin.console from /local/engine/trac-trunk
2009-05-07 16:18:30,830 Trac[loader] DEBUG: Loading trac.db.mysql from /local/engine/trac-trunk
2009-05-07 16:18:30,831 Trac[loader] DEBUG: Loading trac.versioncontrol.admin from /local/engine/trac-trunk
2009-05-07 16:18:30,831 Trac[loader] DEBUG: Loading trac.search from /local/engine/trac-trunk
2009-05-07 16:18:30,831 Trac[loader] DEBUG: Loading trac.prefs from /local/engine/trac-trunk
2009-05-07 16:18:30,831 Trac[loader] DEBUG: Loading trac.ticket.report from /local/engine/trac-trunk
2009-05-07 16:18:30,831 Trac[loader] DEBUG: Loading revtree.enhancer from /local/var/trac/plugins/TracRevtreeLogEnhancer-0.2.0dev_r4024-py2.5.egg
2009-05-07 16:18:30,832 Trac[loader] DEBUG: Loading customfieldadmin.api from /local/var/trac/plugins/TracCustomFieldAdmin-0.2-py2.5.egg
2009-05-07 16:18:30,832 Trac[loader] DEBUG: Loading customfieldadmin.customfieldadmin from /local/var/trac/plugins/TracCustomFieldAdmin-0.2-py2.5.egg
2009-05-07 16:18:30,832 Trac[loader] DEBUG: Loading growl.notifier from /local/var/trac/plugins/TracGrowlPlugin-0.2.1dev_r3950-py2.5.egg
2009-05-07 16:18:30,832 Trac[loader] DEBUG: Loading growl.web_ui from /local/var/trac/plugins/TracGrowlPlugin-0.2.1dev_r3950-py2.5.egg
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.main from /local/engine/bitten
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.master from /local/engine/bitten
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.coverage from /local/engine/bitten
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.web_ui from /local/engine/bitten
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.notify from /local/engine/bitten
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.admin from /local/engine/bitten
2009-05-07 16:18:30,833 Trac[loader] DEBUG: Loading bitten.testing from /local/engine/bitten
2009-05-07 16:18:30,834 Trac[loader] DEBUG: Loading bitten.lint from /local/engine/bitten
2009-05-07 16:18:30,834 Trac[loader] DEBUG: Loading revtree.optimizer from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:30,834 Trac[loader] DEBUG: Loading revtree.web_ui from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:30,834 Trac[loader] DEBUG: Loading revtree.enhancer from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:30,835 Trac[loader] DEBUG: Loading file plugin site from /local/var/trac/plugins/site.py
2009-05-07 16:18:30,841 Trac[chrome] DEBUG: Babel not found: ImportError: No module named babel
2009-05-07 16:18:30,842 Trac[default_workflow] DEBUG: Workflow actions at initialization: {'resolve': {'operations': [u'set_resolution'], 'name': 'resolve', 'default': 0, 'newstate': u'closed', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], 'permissions': [u'TICKET_MODIFY']}, 'accept': {'operations': [u'set_owner_to_self'], 'name': 'accept', 'default': 0, 'newstate': u'accepted', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], 'permissions': [u'TICKET_MODIFY']}, 'leave': {'operations': [u'leave_status'], 'name': 'leave', 'default': 1, 'newstate': u'*', 'oldstates': [u'*'], 'permissions': []}, 'reopen': {'operations': [u'del_resolution'], 'name': 'reopen', 'default': 0, 'newstate': u'reopened', 'oldstates': [u'closed'], 'permissions': [u'TICKET_CREATE']}, 'reassign': {'operations': [u'set_owner'], 'name': 'reassign', 'default': 0, 'newstate': u'assigned', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], 'permissions': [u'TICKET_MODIFY']}, '_reset': {'operations': ['reset_workflow'], 'name': 'reset', 'default': 0, 'newstate': 'new', 'oldstates': [], 'permissions': []}}

2009-05-07 16:18:30,845 Trac[main] DEBUG: Dispatching <Request "GET u'/'">
2009-05-07 16:18:30,869 Trac[api] DEBUG: action controllers for ticket workflow: ['ConfigurableTicketWorkflow']
2009-05-07 16:18:30,874 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:30,909 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:31,184 Trac[main] DEBUG: 942 unreachable objects found.
2009-05-07 16:18:37,850 Trac[main] DEBUG: Dispatching <Request "GET u'/search'">
2009-05-07 16:18:37,857 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:37,881 Trac[main] DEBUG: 46 unreachable objects found.
2009-05-07 16:18:37,889 Trac[main] DEBUG: Dispatching <Request "GET u'/wiki/TestBug'">
2009-05-07 16:18:37,893 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:37,904 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:37,981 Trac[main] DEBUG: 987 unreachable objects found.
2009-05-07 16:18:39,290 Trac[main] DEBUG: Dispatching <Request "GET u'/wiki/TestBug'">
2009-05-07 16:18:39,294 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:39,298 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:39,461 Trac[main] DEBUG: 1150 unreachable objects found.
2009-05-07 16:18:45,159 Trac[loader] DEBUG: Adding plugin TracRevtreeLogEnhancer 0.2.0dev-r4024 from /local/var/trac/plugins/TracRevtreeLogEnhancer-0.2.0dev_r4024-py2.5.egg
2009-05-07 16:18:45,159 Trac[loader] DEBUG: Adding plugin TracCustomFieldAdmin 0.2 from /local/var/trac/plugins/TracCustomFieldAdmin-0.2-py2.5.egg
2009-05-07 16:18:45,160 Trac[loader] DEBUG: Adding plugin TracGrowlPlugin 0.2.1dev-r3950 from /local/var/trac/plugins/TracGrowlPlugin-0.2.1dev_r3950-py2.5.egg
2009-05-07 16:18:45,160 Trac[loader] DEBUG: Adding plugin Bitten 0.6dev-r629 from /local/engine/bitten
2009-05-07 16:18:45,161 Trac[loader] DEBUG: Adding plugin Genshi 0.6dev-r1052 from /local/engine/genshi-trunk
2009-05-07 16:18:45,161 Trac[loader] DEBUG: Adding plugin setuptools 0.6c9 from /usr/lib/python2.5/site-packages
2009-05-07 16:18:45,161 Trac[loader] DEBUG: Adding plugin TracRevtreePlugin 0.6.4dev-r5601 from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:45,161 Trac[loader] DEBUG: Adding plugin Trac 0.12dev-r8176 from /local/engine/trac-trunk
2009-05-07 16:18:45,170 Trac[loader] DEBUG: Loading trac.ticket.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:45,191 Trac[loader] DEBUG: Loading trac.mimeview.php from /local/engine/trac-trunk
2009-05-07 16:18:45,192 Trac[loader] DEBUG: Loading trac.ticket.query from /local/engine/trac-trunk
2009-05-07 16:18:45,195 Trac[loader] DEBUG: Loading trac.attachment from /local/engine/trac-trunk
2009-05-07 16:18:45,195 Trac[loader] DEBUG: Loading trac.versioncontrol.svn_fs from /local/engine/trac-trunk
2009-05-07 16:18:45,202 Trac[loader] DEBUG: Loading trac.mimeview.patch from /local/engine/trac-trunk
2009-05-07 16:18:45,202 Trac[loader] DEBUG: Loading trac.mimeview.txtl from /local/engine/trac-trunk
2009-05-07 16:18:45,208 Trac[loader] DEBUG: Skipping "trac.mimeview.txtl = trac.mimeview.txtl [textile]": ("DistributionNotFound: textile>=2.0" not found)
2009-05-07 16:18:45,208 Trac[loader] DEBUG: Loading trac.admin.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:45,209 Trac[loader] DEBUG: Loading trac.ticket.admin from /local/engine/trac-trunk
2009-05-07 16:18:45,219 Trac[loader] DEBUG: Loading trac.mimeview.rst from /local/engine/trac-trunk
2009-05-07 16:18:45,280 Trac[loader] DEBUG: Loading trac.db.postgres from /local/engine/trac-trunk
2009-05-07 16:18:45,283 Trac[loader] DEBUG: Loading trac.versioncontrol.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:45,284 Trac[loader] DEBUG: Loading trac.timeline from /local/engine/trac-trunk
2009-05-07 16:18:45,285 Trac[loader] DEBUG: Loading trac.mimeview.pygments from /local/engine/trac-trunk
2009-05-07 16:18:45,296 Trac[loader] DEBUG: Loading trac.wiki.admin from /local/engine/trac-trunk
2009-05-07 16:18:45,297 Trac[loader] DEBUG: Loading trac.about from /local/engine/trac-trunk
2009-05-07 16:18:45,297 Trac[loader] DEBUG: Loading trac.wiki.interwiki from /local/engine/trac-trunk
2009-05-07 16:18:45,298 Trac[loader] DEBUG: Loading trac.ticket.roadmap from /local/engine/trac-trunk
2009-05-07 16:18:45,299 Trac[loader] DEBUG: Loading trac.mimeview.silvercity from /local/engine/trac-trunk
2009-05-07 16:18:45,305 Trac[loader] DEBUG: Skipping "trac.mimeview.silvercity = trac.mimeview.silvercity [silvercity]": ("DistributionNotFound: SilverCity>=0.9.4" not found)
2009-05-07 16:18:45,305 Trac[loader] DEBUG: Loading trac.wiki.macros from /local/engine/trac-trunk
2009-05-07 16:18:45,305 Trac[loader] DEBUG: Loading trac.db.sqlite from /local/engine/trac-trunk
2009-05-07 16:18:45,310 Trac[loader] DEBUG: Loading trac.wiki.web_ui from /local/engine/trac-trunk
2009-05-07 16:18:45,311 Trac[loader] DEBUG: Loading trac.mimeview.enscript from /local/engine/trac-trunk
2009-05-07 16:18:45,311 Trac[loader] DEBUG: Loading trac.web.auth from /local/engine/trac-trunk
2009-05-07 16:18:45,314 Trac[loader] DEBUG: Loading trac.admin.console from /local/engine/trac-trunk
2009-05-07 16:18:45,315 Trac[loader] DEBUG: Loading trac.db.mysql from /local/engine/trac-trunk
2009-05-07 16:18:45,319 Trac[loader] DEBUG: Loading trac.versioncontrol.admin from /local/engine/trac-trunk
2009-05-07 16:18:45,319 Trac[loader] DEBUG: Loading trac.search from /local/engine/trac-trunk
2009-05-07 16:18:45,322 Trac[loader] DEBUG: Loading trac.prefs from /local/engine/trac-trunk
2009-05-07 16:18:45,323 Trac[loader] DEBUG: Loading trac.ticket.report from /local/engine/trac-trunk
2009-05-07 16:18:45,324 Trac[loader] DEBUG: Loading revtree.enhancer from /local/var/trac/plugins/TracRevtreeLogEnhancer-0.2.0dev_r4024-py2.5.egg
2009-05-07 16:18:45,328 Trac[loader] DEBUG: Loading customfieldadmin.api from /local/var/trac/plugins/TracCustomFieldAdmin-0.2-py2.5.egg
2009-05-07 16:18:45,328 Trac[loader] DEBUG: Loading customfieldadmin.customfieldadmin from /local/var/trac/plugins/TracCustomFieldAdmin-0.2-py2.5.egg
2009-05-07 16:18:45,329 Trac[loader] DEBUG: Loading growl.notifier from /local/var/trac/plugins/TracGrowlPlugin-0.2.1dev_r3950-py2.5.egg
2009-05-07 16:18:45,332 Trac[loader] DEBUG: Loading growl.web_ui from /local/var/trac/plugins/TracGrowlPlugin-0.2.1dev_r3950-py2.5.egg
2009-05-07 16:18:45,334 Trac[loader] DEBUG: Loading bitten.main from /local/engine/bitten
2009-05-07 16:18:45,335 Trac[loader] DEBUG: Loading bitten.master from /local/engine/bitten
2009-05-07 16:18:45,347 Trac[loader] DEBUG: Loading bitten.coverage from /local/engine/bitten
2009-05-07 16:18:45,347 Trac[loader] DEBUG: Loading bitten.web_ui from /local/engine/bitten
2009-05-07 16:18:45,357 Trac[loader] DEBUG: Loading bitten.notify from /local/engine/bitten
2009-05-07 16:18:45,358 Trac[loader] DEBUG: Loading bitten.admin from /local/engine/bitten
2009-05-07 16:18:45,362 Trac[loader] DEBUG: Loading bitten.testing from /local/engine/bitten
2009-05-07 16:18:45,362 Trac[loader] DEBUG: Loading bitten.lint from /local/engine/bitten
2009-05-07 16:18:45,363 Trac[loader] DEBUG: Loading revtree.optimizer from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:45,364 Trac[loader] DEBUG: Loading revtree.web_ui from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:45,365 Trac[loader] DEBUG: Loading revtree.enhancer from /local/var/trac/plugins/TracRevtreePlugin-0.6.4dev_r5601-py2.5.egg
2009-05-07 16:18:45,366 Trac[loader] DEBUG: Loading file plugin site from /local/var/trac/plugins/site.py
2009-05-07 16:18:45,376 Trac[chrome] DEBUG: Babel not found: ImportError: No module named babel
2009-05-07 16:18:45,377 Trac[default_workflow] DEBUG: Workflow actions at initialization: {'resolve': {'operations': [u'set_resolution'], 'name': 'resolve', 'default': 0, 'newstate': u'closed', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], 'permissions': [u'TICKET_MODIFY']}, 'accept': {'operations': [u'set_owner_to_self'], 'name': 'accept', 'default': 0, 'newstate': u'accepted', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], 'permissions': [u'TICKET_MODIFY']}, 'leave': {'operations': [u'leave_status'], 'name': 'leave', 'default': 1, 'newstate': u'*', 'oldstates': [u'*'], 'permissions': []}, 'reopen': {'operations': [u'del_resolution'], 'name': 'reopen', 'default': 0, 'newstate': u'reopened', 'oldstates': [u'closed'], 'permissions': [u'TICKET_CREATE']}, 'reassign': {'operations': [u'set_owner'], 'name': 'reassign', 'default': 0, 'newstate': u'assigned', 'oldstates': [u'new', u'assigned', u'accepted', u'reopened'], 'permissions': [u'TICKET_MODIFY']}, '_reset': {'operations': ['reset_workflow'], 'name': 'reset', 'default': 0, 'newstate': 'new', 'oldstates': [], 'permissions': []}}

2009-05-07 16:18:45,381 Trac[main] DEBUG: Dispatching <Request "POST u'/wiki/TestBug'">
2009-05-07 16:18:45,408 Trac[api] DEBUG: action controllers for ticket workflow: ['ConfigurableTicketWorkflow']
2009-05-07 16:18:45,413 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:45,439 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:45,456 Trac[main] DEBUG: 9 unreachable objects found.
2009-05-07 16:18:45,462 Trac[main] DEBUG: Dispatching <Request "GET u'/wiki/TestBug'">
2009-05-07 16:18:45,467 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:45,477 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:45,551 Trac[main] DEBUG: 914 unreachable objects found.
2009-05-07 16:18:47,492 Trac[main] DEBUG: Dispatching <Request "GET u'/wiki/TitleIndex'">
2009-05-07 16:18:47,496 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:47,520 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:47,707 Trac[formatter] DEBUG: Executing Wiki macro TitleIndex by provider <trac.wiki.macros.TitleIndexMacro object at 0xa55c22c>
2009-05-07 16:18:47,765 Trac[main] DEBUG: 1193 unreachable objects found.
2009-05-07 16:18:53,693 Trac[main] DEBUG: Dispatching <Request "GET u'/wiki/TitleIndex'">
2009-05-07 16:18:53,698 Trac[chrome] DEBUG: Prepare chrome data for request
2009-05-07 16:18:53,707 Trac[session] DEBUG: Retrieving session for ID 'eblot'
2009-05-07 16:18:53,749 Trac[formatter] DEBUG: Executing Wiki macro TitleIndex by provider <trac.wiki.macros.TitleIndexMacro object at 0x9236a8c>
2009-05-07 16:18:53,810 Trac[main] DEBUG: 1202 unreachable objects found.

Attachments (0)

Change History (8)

comment:1 by Emmanuel Blot, 16 years ago

Owner: set to Remy Blank

comment:2 by Emmanuel Blot, 16 years ago

I forgot to add that all projects are stored within SQLite databases.

comment:3 by Christian Boos, 16 years ago

Keywords: cache added

I did a tiny bit of testing, so far couldn't reproduce the problem. The cache counter increments as expected and all TitleIndex requests were showing the new pages as created. 

# after creating TestBug
sqlite> select * from cache;
trac.wiki.interwiki.InterWikiMap.interwiki_map|0
trac.ticket.api.TicketSystem.fields|3
trac.wiki.api.WikiSystem.pages|0
# after creating TestAnotherBug
sqlite> select * from cache;
trac.wiki.interwiki.InterWikiMap.interwiki_map|0
trac.ticket.api.TicketSystem.fields|3
trac.wiki.api.WikiSystem.pages|1
# etc.

And by looking at top while doing lots of requests on TitleIndex, it seemed that several different httpd processes were indeed used. I'll now test with 2 tracds, the "ultimate" test in this situation ;-)

(using multirepos r8178, sqlite 3.3.8)

comment:4 by Christian Boos, 16 years ago

Ok, reproduced :-(

comment:5 by Christian Boos, 16 years ago

After following two false tracks, I think I finally found the problem. In WikiSystem we have: 

     def has_page(self, pagename):
        """Whether a page with the specified name exists."""
        return pagename.rstrip('/') in self.pages

    # IWikiChangeListener methods

    def wiki_page_added(self, page):
       if not self.has_page(page.name):
            del self.pages

i.e. if the page that has just been added is not in the self.pages cache, invalidate the self.pages cache. But this is flawed, as if we have never looked up self.pages so far, we'll first fetch the list from the wiki table, and the page.name will then be in the cached value of self.pages and we won't invalidate the cache… which means the generation won't change.

So the fix should be to always invalidate the cache, regardless of the presence of the page in the cached values:

  • trac/wiki/api.py

     
    202202    # IWikiChangeListener methods
    203203
    204204    def wiki_page_added(self, page):
    205         if not self.has_page(page.name):
    206             del self.pages
     205        del self.pages
    207206
    208207    def wiki_page_changed(self, page, version, t, comment, author, ipnr):
    209208        pass
    210209
    211210    def wiki_page_deleted(self, page):
    212         if self.has_page(page.name):
    213             del self.pages
     211        del self.pages
    214212
    215213    def wiki_page_version_deleted(self, page):
    216214        pass

The other places where we used cached values need to be reviewed to see if they share the same issue.

Another thing: while testing the reload with mod_wsgi (using touch on the wsgi script), I noticed that the log seems to repeat itself ("le log bégaye ;-)"), like if multiple handlers were still active - this is probably the explanation for #7490, and needs to be investigated further.

in reply to:  5 comment:6 by Remy Blank, 16 years ago

Replying to cboos:

After following two false tracks, I think I finally found the problem.

Hey, cool!

But this is flawed, as if we have never looked up self.pages so far, we'll first fetch the list from the wiki table, and the page.name will then be in the cached value of self.pages and we won't invalidate the cache… which means the generation won't change.

That makes a lot of sense. I had replaced the previous invalidation without thinking enough about the implications, and the difference in the mode of operation of the caches.

The other places where we used cached values need to be reviewed to see if they share the same issue.

Yep, I'll do that tomorrow and test your fix. Thanks!

in reply to:  4 comment:7 by Remy Blank, 16 years ago

Fix tested, works great, applied in [8180]. I have also added a missing invalidation for the InterMapTxt cache when the page is created.

In retrospect, it may be slightly dangerous to only have invalidations triggered explicitly. For Trac core, we can manage the right invalidations (though we do have to be careful. Let's see… yes, there's still an invalidation missing when importing wiki pages from the command line. I'll fix that as well). But what if a plugin inserts e.g. a wiki page or a ticket component directly into the database? It's not supposed to, but then again, you never know.

Should the caches be emptied automatically every hour or so?

comment:8 by Remy Blank, 16 years ago

Resolution: → fixed
Status: new → closed

The missing invalidation when importing wiki pages through trac-admin has been added in [8181] and [8183].

The normal invalidation when using the wiki model has been moved to the model in [8182], so that it can be executed in the same transaction as the page update. This is consistent with how the ticket field cache is handled.

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Remy Blank.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Remy Blank to the specified user.

Add Comment
E-mail address and name can be saved in the Preferences .
Attachments ↑ Description ↑
 
Note: See TracTickets for help on using tickets.