trac-post-commit-hook no longer updates ticket comments

[Patrick Schaaf]

We use the usual SVN trac-post-commit-hook so that commits with refs or fixes in their commit message, cause ticket comments to be added to the referenced tickets.

After installing the AnnouncerPlugin, that no longer happens.

Base trac is 0.11.7. Plugin installed using easy_install http://trac-hacks.org/svn/announcerplugin/0.11. Python 2.6. No change to the problem after I reverted the various small patches I made in the last days, happens with current rev [10458]

The funny thing is that I do receive email notifications, which look correct, contain the SVN commit comment, and for fixes' also purport to make a status change to 'closed'. But no ticket comment appears in the web interface (or in the database; checked with sqlite3 - no modifications to ticket_changed)

I have trac logging at DEBUG level, and see no error messages.

When I disable the announcer modules in [components], and rename back the [announcer] section to [notification], everything returns to normal.

I will try to find the cause, and then attempt a fix. Independant confirmation of the problem, and suggestions, highly welcome!

[Patrick Schaaf]

WORKAROUND indirectly making ticket.save_changes commit before calling out to ticket_changed listeners

[Patrick Schaaf]

Sprinkling debug messages around, I found that trac-post-commit-hook passes in a db to ticket.save_changes. The DB updates are made there, but db.commit is not called in this case before the ticket_changed listeners (and thus AnnouncerPlugin) gets called. The db.commit call is in trac-post-commit-hook after ticket.save_changes completes.

By changing trac-post-commit-hook to just pass None as the db argument to save_changes, as shown in the attached patch, save_changes is made to db.commit before it calls out to the ticket_changed listeners (and thus AnnouncerPlugin). The problem is then gone, the usual ticket comments appear.

As far as I can see, this has no downside, in principle.

However, this analysis points to AnnouncerPlugin ticket_changed doing some things to the database, which makes earlier UPDATE/INSERTs disappear without any notice.

I can imagine this also possibly affecting other plugins using ticket_changed and manipulating the database, so I think it would be good to find the real cause within AnnouncerPlugin. Also making this ticket critical / high priority, for this reason.

Any ideas as to the real cause?

[Patrick Schaaf]

For context, I'm using an sqlite3 DB backend, and the following announcer trac.ini settings:

[components]
announcerplugin.* = enabled
announcerplugin.resolvers.defaultdomain.defaultdomainemailresolver = disabled
announcerplugin.subscriber.ticket_groups.* = disabled
announcerplugin.subscribers.ticket_groups.joinablegroupsubscriber = enabled
announcerplugin.subscribers.watch_users.userchangesubscriber = disabled

[announcer]
ctxtnav_names = Notify, No Notify
admit_domains =
always_notify_owner = true
always_notify_reporter = true
always_notify_updater = false
email_enabled = true
ignore_domains =
joinable_groups = SiteProblems, Analytics, Jokes, JustAnExample
mime_encoding = base64
smtp_always_bcc =
smtp_always_cc =
smtp_default_domain =
smtp_enabled = true
smtp_from = xxx
smtp_from_name = xxx
smtp_password = xxx
smtp_port = 587
smtp_replyto = xxx
smtp_server = xxx
smtp_subject_prefix = __default__
smtp_user = xxx
ticket_subject_template = $prefix #$ticket.id: $summary
use_public_cc = false
use_short_addr = false
use_tls = yes
default_email_format = text/plain

[Steffen Hoffmann]

For Trac-1.0 there relevant modules of tracopt.ticket.commit_updater.CommitTicketUpdater read like so:

    def _update_tickets(self, tickets, changeset, comment, date):
        """Update the tickets with the given comment."""
        perm = PermissionCache(self.env, changeset.author)
        for tkt_id, cmds in tickets.iteritems():
            try:
                self.log.debug("Updating ticket #%d", tkt_id)
                with self.env.db_transaction as db:
                    ticket = Ticket(self.env, tkt_id, db)
                    for cmd in cmds:
                        cmd(ticket, changeset, perm(ticket.resource))
                    ticket.save_changes(changeset.author, comment, date, db)
                self._notify(ticket, date)
            except Exception, e:
                self.log.error("Unexpected error while processing ticket "
                               "#%s: %s", tkt_id, exception_to_unicode(e))
    
    def _notify(self, ticket, date):
        """Send a ticket update notification."""
        if not self.notify:
            return
        try:
            tn = TicketNotifyEmail(self.env)
            tn.notify(ticket, newticket=False, modtime=date)
        except Exception, e:
            self.log.error("Failure sending notification on change to "
                           "ticket #%s: %s", ticket.id,
                           exception_to_unicode(e))

Therefore I conclude, that the issue here is fixed upstream and at least no longer applicable.

[Steffen Hoffmann]

Replying to bof:

Sprinkling debug messages around, I found that trac-post-commit-hook passes in a db to ticket.save_changes. The DB updates are made there, but db.commit is not called in this case before the ticket_changed listeners (and thus AnnouncerPlugin) gets called. The db.commit call is in trac-post-commit-hook after ticket.save_changes completes.

Evidently fixed upstream for 0.12, as far as I can trace it back to ​t:changeset:8094.

However, this analysis points to AnnouncerPlugin ticket_changed doing some things to the database, which makes earlier UPDATE/INSERTs disappear without any notice.

This is not true, at least not for recent/current development code.

I can imagine this also possibly affecting other plugins using ticket_changed and manipulating the database, so I think it would be good to find the real cause within AnnouncerPlugin. Also making this ticket critical / high priority, for this reason.

Sure.

Any ideas as to the real cause?

No, looks all good so far. There is nothing fancy in announcer.api.AnnouncementSystem.send and a big 'catch all' try..except in the _real_send method that it is calling to actually do stuff, so this should never bail out.

The Announcer component in question is dealing with upgrading plugin's db schema in the Trac db. But this happens at Trac environment load and seems entirely unrelated to events happening once Trac is already running.

I really can't afford hunting shadows of the past, sorry. If it was bad, its all gone. Fine with me.