Modify

Opened 14 months ago

Closed 4 months ago

Last modified 4 months ago

#11147 closed defect (fixed)

IntegrityError: duplicate key value violates unique constraint "tags_pk"

Reported by: rjollos Owned by: hasienda
Priority: normal Component: TagsPlugin
Severity: normal Keywords:
Cc: Trac Release:

Description (last modified by rjollos)

I've seen this error from time to time when navigating around since the upgrade, and find the following in the logs. I haven't had a chance to investigate yet. We are running 0.7dev-r13225 of TagsPlugin.

2013-06-06 09:38:22,343 Trac[formatter] ERROR: Macro ListHacks(None) failed:
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/formatter.py", line 765, in _macro_formatter
    return macro.ensure_inline(macro.process(args))
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/formatter.py", line 356, in process
    text = self.processor(text)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/formatter.py", line 343, in _macro_processor
    text)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13235-py2.6.egg/tractags/macros.py", line 158, in expand_macro
    for p in tag_system.tag_providers]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 78, in extensions
    components = [component.compmgr[cls] for cls in classes]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 199, in __getitem__
    component = cls(self)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 138, in __call__
    self.__init__()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13235-py2.6.egg/tractags/ticket.py", line 52, in __init__
    self._fetch_tkt_tags()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13235-py2.6.egg/tractags/ticket.py", line 227, in _fetch_tkt_tags
    """, [(self.realm, str(tkt_id), tag) for tag in ticket_tags])
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/util.py", line 85, in executemany
    return self.cursor.executemany(sql_escape_percent(sql), args)
IntegrityError: duplicate key value violates unique constraint "tags_pk"
IntegrityError: duplicate key value violates unique constraint "tags_pk"

Attachments (1)

ticket11147-fix-for-integrity-error.diff (2.5 KB) - added by jun66j5 9 months ago.

Download all attachments as: .zip

Change History (29)

comment:1 Changed 14 months ago by rjollos

  • Description modified (diff)

Here is another traceback. Note the different forms of the macro call.

2013-06-06 09:22:52,372 Trac[formatter] ERROR: Macro ListTagged(hasienda) failed:
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/formatter.py", line 765, in _macro_formatter
    return macro.ensure_inline(macro.process(args))
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/formatter.py", line 356, in process
    text = self.processor(text)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/formatter.py", line 343, in _macro_processor
    text)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13235-py2.6.egg/tractags/macros.py", line 158, in expand_macro
    for p in tag_system.tag_providers]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 78, in extensions
    components = [component.compmgr[cls] for cls in classes]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 199, in __getitem__
    component = cls(self)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 138, in __call__
    self.__init__()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13235-py2.6.egg/tractags/ticket.py", line 52, in __init__
    self._fetch_tkt_tags()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13235-py2.6.egg/tractags/ticket.py", line 227, in _fetch_tkt_tags
    """, [(self.realm, str(tkt_id), tag) for tag in ticket_tags])
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/util.py", line 85, in executemany
    return self.cursor.executemany(sql_escape_percent(sql), args)
IntegrityError: duplicate key value violates unique constraint "tags_pk"
IntegrityError: duplicate key value violates unique constraint "tags_pk"

comment:2 Changed 14 months ago by hasienda

I've seen this issue in my development setup too, but still have no access to it for some more days.

The worst about it is, that is signals broken sync of ticket tags with tags Trac db table entries. But its not fatal OTOH. I'll definitely try to hunt this down too, because I already had it on my list before releasing tractags-0.7. Nevertheless having a ticket for it is an advantage.

Last edited 9 months ago by rjollos (previous) (diff)

comment:3 Changed 14 months ago by rjollos

I hadn't seen this issue on trac-hacks.org in several days, but saw it on 3 pages just now while updating a bunch of tickets in quick succession.

comment:4 Changed 14 months ago by hasienda

I've been wondering, if the change for [13278] would do something to this issue, but good to have it confirmed. I'll look into this in due time, if no more helpful details will be disclosed before.

comment:5 Changed 11 months ago by rjollos

I've updated trac-hacks.org to the latest TagsPlugin (r13304). After the upgrade I spotted this issue once so far and see tracebacks often in the logs.

2013-08-16 03:17:39,038 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 497, in _dispatch_request
    dispatcher.dispatch(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 214, in dispatch
    resp = chosen_handler.process_request(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/admin/web_ui.py", line 125, in process_request
    path_info)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/admin.py", line 32, in render_admin_panel
    realms = [p.get_taggable_realm() for p in self.tag_providers
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 78, in extensions
    components = [component.compmgr[cls] for cls in classes]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 199, in __getitem__
    component = cls(self)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 138, in __call__
    self.__init__()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/ticket.py", line 52, in __init__
    self._fetch_tkt_tags()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/ticket.py", line 227, in _fetch_tkt_tags
    """, [(self.realm, str(tkt_id), tag) for tag in ticket_tags])
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/util.py", line 85, in executemany
    return self.cursor.executemany(sql_escape_percent(sql), args)
IntegrityError: duplicate key value violates unique constraint "tags_pk"
IntegrityError: duplicate key value violates unique constraint "tags_pk"
2013-08-16 04:31:25,687 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 497, in _dispatch_request
    dispatcher.dispatch(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 233, in dispatch
    content_type)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/chrome.py", line 983, in render_template
    stream |= self._filter_stream(req, method, filename, stream, data)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Genshi-0.6.1-py2.6.egg/genshi/core.py", line 132, in __or__
    return Stream(_ensure(function(self)), serializer=self.serializer)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/chrome.py", line 1162, in inner
    data)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/wiki.py", line 101, in filter_stream
    return self._wiki_view(req, stream)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/wiki.py", line 167, in _wiki_view
    tags = self._page_tags(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/wiki.py", line 162, in _page_tags
    tags = sorted(tag_system.get_tags(req, resource))
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/api.py", line 238, in get_tags
    return set(self._get_provider(resource.realm) \
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/api.py", line 377, in _get_provider
    self._populate_provider_map()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/api.py", line 373, in _populate_provider_map
    for provider in self.tag_providers)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 78, in extensions
    components = [component.compmgr[cls] for cls in classes]
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 199, in __getitem__
    component = cls(self)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/core.py", line 138, in __call__
    self.__init__()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/ticket.py", line 52, in __init__
    self._fetch_tkt_tags()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/TracTags-0.7dev_r13304-py2.6.egg/tractags/ticket.py", line 227, in _fetch_tkt_tags
    """, [(self.realm, str(tkt_id), tag) for tag in ticket_tags])
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/util.py", line 85, in executemany
    return self.cursor.executemany(sql_escape_percent(sql), args)
IntegrityError: duplicate key value violates unique constraint "tags_pk"
IntegrityError: duplicate key value violates unique constraint "tags_pk"

comment:6 Changed 9 months ago by t2y

I encountered the same issue after upgraded 0.6 to 0.7-r13393, and trac version is trac-0.12.1-py2.6. Could you help me?

comment:7 Changed 9 months ago by t2y

And my database is postgresql-8.4.17.
I haven't seen this error message with sqlite though the scale is small.

Changed 9 months ago by jun66j5

comment:8 Changed 9 months ago by jun66j5

Reproduced with Trac 0.12.5 and tractags/trunk r13403 under multiprocess environment and concurrent access.

  1. Setup Trac and tractags with multiprocess > 1 using mod_wsgi, uwsgi, etc...
  2. Launch web server
    $ uwsgi --http :3000 --process 4 --wsgi-file ~/src/trac/tracwsgi.py
    
  3. Concurrent access using apache-bench, etc...
    $ ab -n 4 -c 4 http://localhost:3000/wiki
    

Also, I created a patch for it, attachment:ticket11147-fix-for-integrity-error.diff​. Could you please try the patch?

comment:9 Changed 9 months ago by jun66j5

comment:10 Changed 9 months ago by t2y

Thank you for making patch!
I applied the patch to my trac environment. I will monitor trac.log today, then report the result.

comment:11 Changed 9 months ago by t2y

I confirmed the warning log as below.

2013-10-16 06:56:25,247 Trac[ticket] WARNING: tags for ticket already exist: 
  duplicate key value violates unique constraint "tags_pk"

comment:12 Changed 9 months ago by t2y

I monitored my trac's log today, then confirmed only warning logs (comment:11).
After I applied the patch, I haven't received any complaints. It seems no issue.
Thank you!

comment:13 follow-up: Changed 9 months ago by jun66j5

Thanks for the feedback!

Steffen and Ryan, okay to apply the patch in comment:8?

comment:14 Changed 9 months ago by rjollos

Great as far as I'm concerned, and I'll update TagsPlugin on trac-hacks as soon as the change is pushed.

Steffen is the official maintainer so he has the final say on changes, but if he's not able to respond within a few days, I think it would be best to just push the change. He can always make additional changes later if that's desired.

comment:15 in reply to: ↑ 13 ; follow-up: Changed 9 months ago by hasienda

Replying to jun66j5:

Thanks for the feedback!

Steffen and Ryan, okay to apply the patch in comment:8?

Thanks for your effort. +1 for extending capabilities of this plugin to catch db connection exceptions. So apart from method import order (put get_db_exc in front, please) it looks good. Please commit that. Additionally I'd welcome your unit test fixes too.

Only the SQL optimizations are highly disputable. Here are my observations:

On my development machine the initial sync of an SQLite db holding 30.000 tickets raised from less than 1 s to over 13 min(!), reproducibly. By suppressing some of the changes I deduced, that the more elaborated DELETE statement is causing that delay. While the SELECT on tags table seems fine with the help of the WHERE NOT EXISTS clause, the similar construct does not help with looking through existing ticket IDs. Whether it is the CAST or an abysmal performance of SQLite scanning though ticket (IDs) itself is not clear, but a real show-stopper anyway.

For completeness I mention, that the number of tags is very small compared to the number of tickets in that test scenario. For larger tag quantities I fear that we'll see the nested SELECT on tags consuming a lot more time too. While I agree that dropping all ticket tags does look extremely ugly, it still seems unavoidable for maintaining decent (re-)start performance. I can't imagine professional applications, where even something beyond 20 seconds of init time would be acceptable, not to tell about minutes.

comment:16 Changed 9 months ago by jun66j5

In 13417:

TagsPlugin: fixed a syntax error in unit tests with Python 2.4 (refs #11147)

comment:17 Changed 9 months ago by jun66j5

In 13418:

TagsPlugin: avoid OperationalError: no such table: tags while running unit tests (refs #11147)

comment:18 Changed 9 months ago by jun66j5

In 13419:

TagsPlugin: fixed an IntegrityError while syncing ticket fields and tags table on concurrent access (refs #11147)

comment:19 in reply to: ↑ 15 ; follow-up: Changed 9 months ago by jun66j5

Replying to hasienda:

Thanks for your effort. +1 for extending capabilities of this plugin to catch db connection exceptions. So apart from method import order (put get_db_exc in front, please) it looks good. Please commit that. Additionally I'd welcome your unit test fixes too.

Thanks for the reply. I've pushed the fixes with your suggestions for IntegrityError and unit tests in [13417-13419].

On my development machine the initial sync of an SQLite db holding 30.000 tickets raised from less than 1 s to over 13 min(!), reproducibly. By suppressing some of the changes I deduced, that the more elaborated DELETE statement is causing that delay. While the SELECT on tags table seems fine with the help of the WHERE NOT EXISTS clause, the similar construct does not help with looking through existing ticket IDs. Whether it is the CAST or an abysmal performance of SQLite scanning though ticket (IDs) itself is not clear, but a real show-stopper anyway.

Oh, that is so bad. The ticket11147 branch has full-scan in DELETE query. I've reworked in ticket11147.2 branch. This changes use index for ticket.id column while executing DELETE query. Could you please try it?

comment:20 in reply to: ↑ 19 ; follow-up: Changed 9 months ago by hasienda

Replying to jun66j5:

Replying to hasienda:

On my development machine the initial sync of an SQLite db holding 30.000 tickets raised from less than 1 s to over 13 min(!), reproducibly. By suppressing some of the changes I deduced, that the more elaborated DELETE statement is causing that delay. While the SELECT on tags table seems fine with the help of the WHERE NOT EXISTS clause, the similar construct does not help with looking through existing ticket IDs. Whether it is the CAST or an abysmal performance of SQLite scanning though ticket (IDs) itself is not clear, but a real show-stopper anyway.

Oh, that is so bad. The ticket11147 branch has full-scan in DELETE query. I've reworked in ticket11147.2 branch. This changes use index for ticket.id column while executing DELETE query. Could you please try it?

Amazing. Just using the indexed column does the trick indeed. Initial sync latency stays below 1 s with optimizations in place now - good to go from my point of view, and thanks for a nice piece of SQL foo.

comment:21 Changed 9 months ago by rjollos

t-h.o has been updated to TracTags 0.7dev-r13419. Thanks!

comment:22 in reply to: ↑ 20 ; follow-up: Changed 9 months ago by hasienda

Replying to hasienda:

Replying to jun66j5:

Oh, that is so bad. ... I've reworked in ticket11147.2 branch. This changes use index for ticket.id column while executing DELETE query. Could you please try it?

Amazing. Just using the indexed column does the trick indeed. Initial sync latency stays below 1 s with optimizations in place now - good to go from my point of view, and thanks for a nice piece of SQL foo.

Any reason other than time for not applying your latest draft of SQL optimization?

And thanks to Ryan for updating the installation at t-h.o, that is a serious test case too.

comment:23 in reply to: ↑ 22 ; follow-up: Changed 9 months ago by jun66j5

Replying to hasienda:

Any reason other than time for not applying your latest draft of SQL optimization?

I have another suggestion, again. Even after 7bba2e1, first request leads large transaction while synchronizing ticket attributes to tags table with many ticket records.

I think that upgrade_environment() should do initial sync instead of first request. Then the transaction in TicketTagProvider.__init__ would be small, see 15e64a5.

Version 0, edited 9 months ago by jun66j5 (next)

comment:24 in reply to: ↑ 23 Changed 9 months ago by hasienda

Replying to jun66j5:

... , first request leads large transaction while synchronizing ticket attributes to tags table with many ticket records.

I think that upgrade_environment() should do initial sync instead of first request. Then the transaction in TicketTagProvider.__init__() for first request would be small, see 15e64a5.

Good catch, because I did not care to remove ticket tags before re-testing. I like the way you push it to an even more convenient state. Please, go on with that.

comment:25 Changed 9 months ago by jun66j5

In 13425:

TagsPlugin: optimize synchronization ticket attributes to tags table (refs #11147)

comment:26 Changed 9 months ago by jun66j5

In 13426:

TagsPlugin: upgrade_environment() synchronizes ticket attributes to tags table in order to reduce transactions in TicketTagProvider._fetch_tkt_tags() on first request (refs #11147)

comment:27 Changed 4 months ago by hasienda

  • Resolution set to fixed
  • Status changed from new to closed

In 13815:

TagsPlugin: Completing preparation for v0.7 release.

Availability of that code as stable, tagged release
closes #2429, #3359, #3610, #3624, #3677, #3754, #3864, #3947, #3983, #4078, #4277, #4503, #4799, #5523, #7787, #7857, #8638, #9057, #9058, #9059, #9060, #9061, #9062, #9063, #9149, #9210, #9521, #9630, #9636, #10032, #10416, #10636, #11096, #11147, #11152, #11274, #11302, #11658 and #11659.

Additionally there are some issues and enhancement requests showing progress,
but known to require more work to resolve them satisfactorily, specifically
refs #2804, #4200, #8747 and #9064.

Thanks to all contributors and followers, that enabled and encouraged a good
portion of this development work.

comment:28 Changed 4 months ago by t2y

Thank you, too!

Add Comment

Modify Ticket

Action
as closed .
as The resolution will be set. Next status will be 'closed'.
to The owner will be changed from hasienda. Next status will be 'closed'.
The resolution will be deleted. Next status will be 'reopened'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.