Uploaded image for project: 'SR for Bitbucket - Development'
  1. SR for Bitbucket - Development
  2. SRBITB-270

Event Handlers have duplicate runs when multiple events of the same type are published and handled asynchronously

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Done
    • High
    • Resolution: Fixed
    • 5.2.2
    • 5.3.8
    • None
    • None
    • Sprint 37 - Ends Nov 28
    • 0

    Description

      As an example, try creating an event listener on one of the RefRestrictionEvent classes (which listen for branch permissions). These events actually come from one of the plugins in Bitbucket's architecture.

      import com.onresolve.scriptrunner.bitbucket.BitbucketEventListener
      import com.onresolve.scriptrunner.runner.ScriptRunnerImpl
      import com.onresolve.scriptrunner.runner.rest.AbstractConfiguredItemsRestEndpoint
      import com.onresolve.scriptrunner.runner.util.AOPropertyPersister
      
      def listeners = AOPropertyPersister.loadList(BitbucketEventListener.AO_PROPERTY_KEY)
      log.debug listeners
      
      def listenerConfig = [
      "FIELD_INLINE_SCRIPT" : '',
      "FIELD_SCRIPT_FILE" : 'examples/bitbucket/RefRestrictions.groovy',
      "FIELD_NOTES" : "Block changes to branch permissions",
      "FIELD_PER_REPO_ID" : '',
      "FIELD_PROJECT_REPO_IDS" : ["repo:-1"],
      "canned-script" : 'com.onresolve.scriptrunner.canned.bitbucket.events.SimpleScriptedEventHandler',
      "events" : [
      //'com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionEvent',
      //'com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionDeletedEvent',
      'com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionAddedEvent'
      ],
      ]
      
      listenerConfig["id"] = AbstractConfiguredItemsRestEndpoint.itemHashCode(listenerConfig)
      
      listeners << listenerConfig
      listeners.unique(true)
      
      AOPropertyPersister.save(listeners, BitbucketEventListener.AO_PROPERTY_KEY)
      
      def stashEventListener = ScriptRunnerImpl.getPluginComponent(BitbucketEventListener)
      stashEventListener.refresh()
      

      The file referenced (examples/bitbucket/RefRestrictions.groovy) should be in a script root with the following code:

      import com.atlassian.bitbucket.audit.AuditEntryBuilder
      import com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionEvent
      import com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionEventConverter
      import com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionService
      import com.atlassian.sal.api.component.ComponentLocator
      
      RefRestrictionEvent event = event as RefRestrictionEvent
      log.debug "Ref restriction event fired"
      def refRestrictionService = ComponentLocator.getComponent(RefRestrictionService)
      
      log.debug "Class: ${event.getClass()}"
      log.debug "Restriction: ${event.restriction.accessGrants}"
      log.debug "Restriction: ${event.restriction.type}"
      log.debug "Id: ${event.restriction.id}"
      
      log.debug "Audit log entry"
      def converter = new RefRestrictionEventConverter()
      def auditLog = converter.convert(event, new AuditEntryBuilder())
      log.debug auditLog.toString()
      

      If you then create a set of branch permissions with more than one permission, you'll get redundant logs.

      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - Ref restriction event fired
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - Ref restriction event fired
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - Ref restriction event fired
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - Ref restriction event fired
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - Class: class com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionAddedEvent
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - Class: class com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionAddedEvent
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - Class: class com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionAddedEvent
      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - Class: class com.atlassian.bitbucket.repository.ref.restriction.RefRestrictionAddedEvent
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: [com.atlassian.stash.internal.repository.ref.restriction.SimpleUserAccessGrant@b718581]
      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: [com.atlassian.stash.internal.repository.ref.restriction.SimpleUserAccessGrant@b718581]
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: [com.atlassian.stash.internal.repository.ref.restriction.SimpleUserAccessGrant@b718581]
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: [com.atlassian.stash.internal.repository.ref.restriction.SimpleUserAccessGrant@b718581]
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: READ_ONLY
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: READ_ONLY
      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: READ_ONLY
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - Restriction: READ_ONLY
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - Id: 21
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - Id: 21
      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - Id: 21
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - Audit log entry
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - Audit log entry
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - Id: 21
      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - Audit log entry
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - Audit log entry
      2017-11-16 15:34:08 [AtlassianEvent::thread-1] DEBUG c.o.s.runner.ScriptRunnerImpl - com.atlassian.bitbucket.audit.AuditEntryBuilder$SimpleAuditEntry@7aa302bd
      2017-11-16 15:34:08 [AtlassianEvent::thread-6] DEBUG c.o.s.runner.ScriptRunnerImpl - com.atlassian.bitbucket.audit.AuditEntryBuilder$SimpleAuditEntry@2d14db3b
      2017-11-16 15:34:08 [AtlassianEvent::thread-2] DEBUG c.o.s.runner.ScriptRunnerImpl - com.atlassian.bitbucket.audit.AuditEntryBuilder$SimpleAuditEntry@7969556f
      2017-11-16 15:34:08 [AtlassianEvent::thread-5] DEBUG c.o.s.runner.ScriptRunnerImpl - com.atlassian.bitbucket.audit.AuditEntryBuilder$SimpleAuditEntry@49fe0708
      

      Compare that to what shows up in the repository's audit log:

      AdministratorAdministrator
      RefRestrictionAddedEvent	{"id":24,"type":"no-deletes","matcher":"refs/heads/branch_mod_merge","matcherType":"Branch","users":["admin"]}	27 mins ago
      AdministratorAdministrator
      RefRestrictionAddedEvent	{"id":23,"type":"pull-request-only","matcher":"refs/heads/branch_mod_merge","matcherType":"Branch","users":["admin"]}	27 mins ago
      AdministratorAdministrator
      RefRestrictionAddedEvent	{"id":22,"type":"fast-forward-only","matcher":"refs/heads/branch_mod_merge","matcherType":"Branch","users":["admin"]}	27 mins ago
      AdministratorAdministrator
      RefRestrictionAddedEvent	{"id":21,"type":"read-only","matcher":"refs/heads/branch_mod_merge","matcherType":"Branch","users":["admin"]}	27 mins ago
      

      This doesn't seem to happen with a comparable Bitbucket Server plugin, which will log each branch permission granted independently. https://bitbucket.org/jonnycarteradaptavist/bitbucket-branch-permission-blocker

      By debugging, you can see that the DynamicEventListenerInvoker only actually hits a breakpoint in its invoke method once, even though the event handler script runs four times.

      If you disable handling events asynchronously you get the expected result.

      It's likely this is a threading issue with the way we run event handlers.

      Attachments

        Activity

          People

            amarkham Adam Markham
            jcarter Jonny Carter
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: