Uploaded image for project: 'Bamboo Data Center'
  1. Bamboo Data Center
  2. BAM-9687

Possible race condition for build label addition

    XMLWordPrintable

Details

    • Bug
    • Resolution: Fixed
    • Low
    • 3.3 final, 3.3
    • 3.1.4
    • Builds
    • None
    • CentOS 5.5 JDK 1.6.0_24

    Description

      A couple of days ago we started getting error messages back from many of our builds along the lines of the following:

      System Error Details
      xxx - 6. yyy - Default Job 10 : Build Labeller custom build post complete action failed to run 
      (java.lang.RuntimeException : Cannot add label '15_0_05_0917' to build results 'xxxxx-yyy-JOB1-10')
      
      Occurred: 02 Sep 2011, 6:02:53 AM
      java.lang.RuntimeException: Cannot add label '15_0_05_0917' to build results 'xxx-yyy-JOB1-10'
      	at com.atlassian.bamboo.labels.LabelManagerImpl.addLabel(LabelManagerImpl.java:92)
      	at sun.reflect.GeneratedMethodAccessor1147.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      	at java.lang.reflect.Method.invoke(Method.java:597)
      	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
      	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
      	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      	at $Proxy42.addLabel(Unknown Source)
      	at sun.reflect.GeneratedMethodAccessor1147.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      	at java.lang.reflect.Method.invoke(Method.java:597)
      	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
      	at com.atlassian.bamboo.security.acegi.intercept.aopalliance.AuthorityOverrideMethodSecurityInterceptor.invoke(AuthorityOverrideMethodSecurityInterceptor.java:30)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
      	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      	at $Proxy42.addLabel(Unknown Source)
      	at com.atlassian.bamboo.plugins.labeller.BuildLabeller.labelBuildResult(BuildLabeller.java:304)
      	at com.atlassian.bamboo.plugins.labeller.BuildLabeller.labelBuildResult(BuildLabeller.java:291)
      	at com.atlassian.bamboo.plugins.labeller.BuildLabeller.call(BuildLabeller.java:85)
      	at sun.reflect.GeneratedMethodAccessor712.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      	at java.lang.reflect.Method.invoke(Method.java:597)
      	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
      	at org.springframework.orm.hibernate.HibernateInterceptor.invoke(HibernateInterceptor.java:117)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
      	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      	at $Proxy362.call(Unknown Source)
      	at com.atlassian.bamboo.v2.build.events.PostBuildCompletedEventListener$1.run(PostBuildCompletedEventListener.java:71)
      	at com.atlassian.bamboo.variable.CustomVariableContextRunnerImpl.execute(CustomVariableContextRunnerImpl.java:25)
      	at com.atlassian.bamboo.v2.build.events.PostBuildCompletedEventListener.performAction(PostBuildCompletedEventListener.java:52)
      	at com.atlassian.bamboo.v2.build.events.PostBuildCompletedEventListener.handleEvent(PostBuildCompletedEventListener.java:41)
      	at com.atlassian.event.legacy.LegacyListenerHandler$LegacyListenerInvoker.invoke(LegacyListenerHandler.java:55)
      	at com.atlassian.event.internal.AsynchronousAbleEventDispatcher$2.run(AsynchronousAbleEventDispatcher.java:60)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      	at com.atlassian.bamboo.build.pipeline.concurrent.NamedThreadFactory$2.run(NamedThreadFactory.java:50)
      	at java.lang.Thread.run(Thread.java:662)
      Caused by: org.springframework.dao.IncorrectResultSizeDataAccessException: query did not return a unique result: 2
      	at org.springframework.orm.hibernate.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:590)
      	at org.springframework.orm.hibernate.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:353)
      	at org.springframework.orm.hibernate.HibernateTemplate.execute(HibernateTemplate.java:375)
      	at org.springframework.orm.hibernate.HibernateTemplate.execute(HibernateTemplate.java:337)
      	at com.atlassian.bamboo.labels.LabelHibernateDao.findLabelByNameAndNamespace(LabelHibernateDao.java:35)
      	at sun.reflect.GeneratedMethodAccessor1269.invoke(Unknown Source)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      	at java.lang.reflect.Method.invoke(Method.java:597)
      	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
      	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
      	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
      	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
      	at $Proxy13.findLabelByNameAndNamespace(Unknown Source)
      	at com.atlassian.bamboo.labels.LabelManagerImpl.addLabel(LabelManagerImpl.java:392)
      	at com.atlassian.bamboo.labels.LabelManagerImpl$1.call(LabelManagerImpl.java:80)
      	at com.atlassian.bamboo.labels.LabelManagerImpl$1.call(LabelManagerImpl.java:75)
      	at com.atlassian.bamboo.labels.LabelManagerImpl.withWriteLock(LabelManagerImpl.java:207)
      	at com.atlassian.bamboo.labels.LabelManagerImpl.addLabel(LabelManagerImpl.java:74)
      	... 43 more
      

      This happened for two separate and widely-used labels.
      It was pretty obvious from the hibernate exception that Bamboo had created duplicate labels in the DB.
      We ended up renaming the duplicate label and telling any builds that referenced it to use the original label.
      The relevant database contents prior to the fix were as follows:

      mysql> select * from LABEL where NAME="14_0_36_21";
      +----------+------------+-----------+---------------------+---------------------+
      | LABEL_ID | NAME       | NAMESPACE | CREATED_DATE        | UPDATED_DATE        |
      +----------+------------+-----------+---------------------+---------------------+
      | 55410738 | 14_0_36_21 | label     | 2011-09-02 05:08:56 | 2011-09-02 05:08:56 |
      | 55410739 | 14_0_36_21 | label     | 2011-09-02 05:08:56 | 2011-09-02 05:08:56 |
      +----------+------------+-----------+---------------------+---------------------+
      2 rows in set (0.00 sec)
      
      mysql> select * from BUILDRESULTSUMMARY_LABEL where LABEL_ID="55410738";
      +----------+----------+-----------------------+----------+------------+-----------+---------------------+---------------------+
      | ID       | LABEL_ID | BUILDRESULTSUMMARY_ID | BUILD_ID | PROJECT_ID | USER_NAME | CREATED_DATE        | UPDATED_DATE        |
      +----------+----------+-----------------------+----------+------------+-----------+---------------------+---------------------+
      | 55345686 | 55410738 |              55054288 | 44367885 |   43155458 | NULL      | 2011-09-02 05:08:56 | 2011-09-02 05:08:56 |
      +----------+----------+-----------------------+----------+------------+-----------+---------------------+---------------------+
      1 row in set (0.00 sec)
      
      mysql> select * from BUILDRESULTSUMMARY_LABEL where LABEL_ID="55410739";
      +----------+----------+-----------------------+----------+------------+-----------+---------------------+---------------------+
      | ID       | LABEL_ID | BUILDRESULTSUMMARY_ID | BUILD_ID | PROJECT_ID | USER_NAME | CREATED_DATE        | UPDATED_DATE        |
      +----------+----------+-----------------------+----------+------------+-----------+---------------------+---------------------+
      | 55345687 | 55410739 |              55054290 | 51183804 |   43155458 | NULL      | 2011-09-02 05:08:56 | 2011-09-02 05:08:56 |
      +----------+----------+-----------------------+----------+------------+-----------+---------------------+---------------------+
      1 row in set (0.00 sec)
      
      
      mysql> select * from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY_ID="55054288";
      +-----------------------+---------------------+---------------------+----------------------+--------------+-------------+-----------------------+-------------------+---------------------+----------------------+----------+-------------+--------------------------------------------------------------------------+--------------+-------------+----------------+---------------------+---------------------+--------------------+--------------------+------------------+-------------------+---------------------+------------------+---------------------+----------------+------------+------------------+----------------------+-----------------------+--------------+
      | BUILDRESULTSUMMARY_ID | CREATED_DATE        | UPDATED_DATE        | BUILD_KEY            | BUILD_NUMBER | BUILD_STATE | SUCCESSFUL_TEST_COUNT | FAILED_TEST_COUNT | BUILD_DATE          | BUILD_COMPLETED_DATE | DURATION | TIME_TO_FIX | TRIGGER_REASON                                                           | REVISION_KEY | DELTA_STATE | BUILD_AGENT_ID | VCS_UPDATE_TIME     | QUEUE_TIME          | FAILURE_TEST_COUNT | SUCCESS_TEST_COUNT | TOTAL_TEST_COUNT | BROKEN_TEST_COUNT | EXISTING_TEST_COUNT | FIXED_TEST_COUNT | TOTAL_TEST_DURATION | STAGERESULT_ID | BUILD_TYPE | LIFE_CYCLE_STATE | BUILD_CANCELLED_DATE | SKIPPED_COMMITS_COUNT | CHAIN_RESULT |
      +-----------------------+---------------------+---------------------+----------------------+--------------+-------------+-----------------------+-------------------+---------------------+----------------------+----------+-------------+--------------------------------------------------------------------------+--------------+-------------+----------------+---------------------+---------------------+--------------------+--------------------+------------------+-------------------+---------------------+------------------+---------------------+----------------+------------+------------------+----------------------+-----------------------+--------------+
      |              55054288 | 2011-09-02 05:01:09 | 2011-09-02 05:08:55 | yyy-JOB1 |         3149 | Successful  |                  NULL |              NULL | 2011-09-02 05:02:22 | 2011-09-02 05:03:30  |    68367 |        NULL | com.atlassian.bamboo.plugin.system.triggerReason:DependencyTriggerReason | 17035        | NONE        |       41353237 | 2011-09-02 05:01:09 | 2011-09-02 05:01:09 |                  0 |                  0 |                0 |                 0 |                   0 |                0 |                   0 |       55085118 | BUILD      | Finished         | NULL                 |                     0 |     55054287 |
      +-----------------------+---------------------+---------------------+----------------------+--------------+-------------+-----------------------+-------------------+---------------------+----------------------+----------+-------------+--------------------------------------------------------------------------+--------------+-------------+----------------+---------------------+---------------------+--------------------+--------------------+------------------+-------------------+---------------------+------------------+---------------------+----------------+------------+------------------+----------------------+-----------------------+--------------+
      1 row in set (0.00 sec)
      
      mysql> select * from BUILDRESULTSUMMARY where BUILDRESULTSUMMARY_ID="55054290";
      +-----------------------+---------------------+---------------------+--------------------------+--------------+-------------+-----------------------+-------------------+---------------------+----------------------+----------+-------------+--------------------------------------------------------------------------+--------------+-------------+----------------+---------------------+---------------------+--------------------+--------------------+------------------+-------------------+---------------------+------------------+---------------------+----------------+------------+------------------+----------------------+-----------------------+--------------+
      | BUILDRESULTSUMMARY_ID | CREATED_DATE        | UPDATED_DATE        | BUILD_KEY                | BUILD_NUMBER | BUILD_STATE | SUCCESSFUL_TEST_COUNT | FAILED_TEST_COUNT | BUILD_DATE          | BUILD_COMPLETED_DATE | DURATION | TIME_TO_FIX | TRIGGER_REASON                                                           | REVISION_KEY | DELTA_STATE | BUILD_AGENT_ID | VCS_UPDATE_TIME     | QUEUE_TIME          | FAILURE_TEST_COUNT | SUCCESS_TEST_COUNT | TOTAL_TEST_COUNT | BROKEN_TEST_COUNT | EXISTING_TEST_COUNT | FIXED_TEST_COUNT | TOTAL_TEST_DURATION | STAGERESULT_ID | BUILD_TYPE | LIFE_CYCLE_STATE | BUILD_CANCELLED_DATE | SKIPPED_COMMITS_COUNT | CHAIN_RESULT |
      +-----------------------+---------------------+---------------------+--------------------------+--------------+-------------+-----------------------+-------------------+---------------------+----------------------+----------+-------------+--------------------------------------------------------------------------+--------------+-------------+----------------+---------------------+---------------------+--------------------+--------------------+------------------+-------------------+---------------------+------------------+---------------------+----------------+------------+------------------+----------------------+-----------------------+--------------+
      |              55054290 | 2011-09-02 05:02:17 | 2011-09-02 05:08:55 | xxx-JOB1 |          667 | Successful  |                  NULL |              NULL | 2011-09-02 05:03:40 | 2011-09-02 05:05:58  |   137913 |        NULL | com.atlassian.bamboo.plugin.system.triggerReason:DependencyTriggerReason | 17035        | NONE        |       33128455 | 2011-09-02 05:02:18 | 2011-09-02 05:02:17 |                  0 |                  0 |                0 |                 0 |                   0 |                0 |                   0 |       55085119 | BUILD      | Finished         | NULL                 |                     0 |     55054289 |
      +-----------------------+---------------------+---------------------+--------------------------+--------------+-------------+-----------------------+-------------------+---------------------+----------------------+----------+-------------+--------------------------------------------------------------------------+--------------+-------------+----------------+---------------------+---------------------+--------------------+--------------------+------------------+-------------------+---------------------+------------------+---------------------+----------------+------------+------------------+----------------------+-----------------------+--------------+
      1 row in set (0.01 sec)
      
      mysql> select * from BUILD where BUILD_ID="44367885";
      +----------+---------------------+---------------------+----------------------+----------+-------------+--------------+--------------------+---------------------+-------------------+-------------------------+---------------------+------------+------------------+-----------------+------------+-------------+----------+
      | BUILD_ID | CREATED_DATE        | UPDATED_DATE        | FULL_KEY             | BUILDKEY | TITLE       | REVISION_KEY | FIRST_BUILD_NUMBER | LATEST_BUILD_NUMBER | NEXT_BUILD_NUMBER | SUSPENDED_FROM_BUILDING | MARKED_FOR_DELETION | PROJECT_ID | NOTIFICATION_SET | REQUIREMENT_SET | BUILD_TYPE | DESCRIPTION | STAGE_ID |
      +----------+---------------------+---------------------+----------------------+----------+-------------+--------------+--------------------+---------------------+-------------------+-------------------------+---------------------+------------+------------------+-----------------+------------+-------------+----------+
      | 44367885 | 2011-07-03 06:10:37 | 2011-09-02 13:01:18 | yyy-JOB1 | JOB1     | Default Job | 17073        |                  1 |                3157 |              3158 |                         |                     |   43155458 |         44466189 |        44400653 | JOB        |             | 44335117 |
      +----------+---------------------+---------------------+----------------------+----------+-------------+--------------+--------------------+---------------------+-------------------+-------------------------+---------------------+------------+------------------+-----------------+------------+-------------+----------+
      1 row in set (0.00 sec)
      
      mysql> select * from BUILD where BUILD_ID="51183804";
      +----------+---------------------+---------------------+--------------------------+----------+-------------+--------------+--------------------+---------------------+-------------------+-------------------------+---------------------+------------+------------------+-----------------+------------+-------------+----------+
      | BUILD_ID | CREATED_DATE        | UPDATED_DATE        | FULL_KEY                 | BUILDKEY | TITLE       | REVISION_KEY | FIRST_BUILD_NUMBER | LATEST_BUILD_NUMBER | NEXT_BUILD_NUMBER | SUSPENDED_FROM_BUILDING | MARKED_FOR_DELETION | PROJECT_ID | NOTIFICATION_SET | REQUIREMENT_SET | BUILD_TYPE | DESCRIPTION | STAGE_ID |
      +----------+---------------------+---------------------+--------------------------+----------+-------------+--------------+--------------------+---------------------+-------------------+-------------------------+---------------------+------------+------------------+-----------------+------------+-------------+----------+
      | 51183804 | 2011-08-05 02:01:37 | 2011-09-02 13:01:19 | xxx-JOB1 | JOB1     | Default Job | 17073        |                330 |                 675 |               676 |                         |                     |   43155458 |         51249340 |        51216523 | JOB        |             | 51150929 |
      +----------+---------------------+---------------------+--------------------------+----------+-------------+--------------+--------------------+---------------------+-------------------+-------------------------+---------------------+------------+------------------+-----------------+------------+-------------+----------+
      1 row in set (0.00 sec)
      

      We hit a very similar issue with a plan creation race condition (BAM-9231) recently.
      This appears to be caused by a separate race condition affecting the creation of labels.

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              b0d88db9bee7 David Corley
              Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: