Rational Build Forge builds get stuck in Any state in Rational Team Concert

Authors: IntegrationsTroubleshootingTeam
Build basis: RTC 4.x and later

The Rational Build Forge and IBM Engineering Workflow Management (EWM), formerly - Rational Team Concert (RTC), integration has two task loops that run continuously,

• Build loop

The build loop's responsibility is to continuously check for a EWM (RTC) build request with a Build Forge contributor to pick up. When such a request is found, EWM will flip the build request from the Pending state to the Running state. This will also connect to Build Forge and start the corresponding build there.

• Event loop.

The event loop will poll Build Forge looking for EWM events that have been generated in Build Forge. When those events are found it will parse the event and change the state of the build correspondingly.

Knowing this basic concept how do we troubleshoot the build requests become stuck in a state? If you are using RTC 3.0.1.2 or earlier, it is likely you are hitting a defect with how the connection logic was handled. There was an issue with uncaught exceptions bypassing the event logic, which caused builds to never process the appropriate events. The events only persist in Build Forge for 20 minutes and if they are not picked up by then the event is gone for good and there is nothing that will change the state of the RTC build. The build is effectively 'stuck' in whatever state it is in. This case could also occur if the RTC server is brought down for more than 20 minutes with active Build Forge integrated builds running. In either case, the events that would change the state of the build would be gone, leaving the RTC build in stasis forever. This assumes that the build is out of the pending state.

If the builds are stuck in pending state, and the build is not started in Build Forge, then the problem is the build loop. It could be that the loop is not running due to some system setting (e.g. Migration Mode Enabled set to true), or some kind of service error with the build loop task.

Investigating the problem.

Note: As of ELM versions 7.0.1 SR1 / 7.0.2 SR1 the log4j.properties file has been changed to log4j2.xml.

To drill deeper into the Build and Sync Loop, enable the debugging in the Change and Configuration Management (CCM) as followws:

Prior to versions 7.0.1 SR1 / 7.0.2 SR2: log4j.properties file by changing the line

    log4j.logger.com.ibm.rational.buildforge= *WARN* 

to

    log4j.logger.com.ibm.rational.buildforge= *DEBUG* 

For versions 7.0.1 SR1 / 7.0.2 SR2 and beyond: log4j2.xml file by changing the section from

    <logger name="com.ibm.rational.buildforge" level="WARN"/>

to

    <logger name="com.ibm.rational.buildforge" level="DEBUG"/>

The CCM log will start filling up with Build Forge integration debug data.

This log entry shows the build getting picked up initially by EWM:

2013-11-09 20:13:09,179 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - configurationData: Build definition: BuildForge_JBE build
    Project name: BF_Project_JBE
    Project uuid: 5d0d75490c601000bdeea3917cfe7cfe
    Host name: localhost
    Secure connection: true
    Port: 3966
    Server key: localhost:3966
    User id: null
    All logs: true
    All logs not passed or skipped: false
    Custom BOM enabled: true
    Num first logs:: 5
    First logs enabled: false
    Num last logs: 5
    Last logs enabled: false
2013-11-09 20:13:09,179 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - engineConfigurationData: Engine ID: BF_engineEngine UUID: _5pI9YIG6EeKAxNIURYE-1w
    Has configuration: true
    Host name: 9.142.57.67
    Secure connection: false
    Port: 3966
    Server key: 9.142.57.67:3966
    User id: build
2013-11-09 20:13:09,270 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - buildPropsMap: {scheduledBuild=true, buildEngineHostName=default, buildResultUuid=default, team.scm.deliver.componentsToDeliver=, buildEngineId=default, team.scm.deliver.addNewComponentsToTarget=false, Build_Password=jazzadmin, personalBuild=false, Build_Engine_Path=c:\JazzBuild\jazz\buildsystem\buildengine\eclipse, buildRequesterUserId=default, team.scm.deliver.changeSnapshotOwner=false, team.scm.componentLoadRules=, team.scm.deliver.enabled=true, team.scm.fetchDestination=C:\BF_Build, Build_Toolkit_Path=C:\JazzBuild\jazz\buildsystem\buildtoolkit, ANT_HOME=C:\Eclipse\jazz\client\eclipse\plugins\org.apache.ant_1.7.1.v20100518-1145, team.scm.deliver.targetUUID=_jITNsIG6EeKhEIJR9zCjrA, buildLabelPrefix=T, JAVA_HOME=C:\Program Files\Java\jdk1.7.0_15, team.scm.deliver.triggerPolicy=NO_ERRORS, buildLabel=Zee_build, buildResultUUID=default, com.ibm.team.build.internal.template.id=com.ibm.rational.connector.buildforge.ui.buildDefinitionTemplate, buildEngineID=BF_Engine, team.scm.workspaceUUID=_LaCWsIG8EeKhEIJR9zCjrA, team.scm.buildOnlyIfChanges=true, team.scm.deliver.abortOnIncompleteActivity=false, team.scm.acceptBeforeFetch=true, team.scm.createFoldersForComponents=false, team.scm.deleteDestinationBeforeFetch=true, team.scm.deliver.removeComponentsInTarget=false, team.scm.includeComponents=false, Build_User=jazzadmin, engineUUID=default, team.scm.deliver.deliverAllComponents=true, team.scm.loadComponents=, Repository_Address=https://9.142.63.252:9443/ccm}

2013-11-09 20:13:09,271 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - IBuildResult: com.ibm.team.build.internal.common.model.impl.BuildResultImpl@2fe92fe9 (stateId: [UUID _QuJe0kmlEeOn_u3QK8c59g], itemId: [UUID _OxgzAEmlEeOn_u3QK8c59g], origin: <unset>, immutable: true) (contextId: [UUID _fTQ10IG6EeKAxNIURYE-1w], modified: 2013-11-09 20:13:09.181, workingCopy: false) (mergePredecessor: null, workingCopyPredecessor: null, workingCopyMergePredecessor: null, predecessor: [UUID _Ox3YVkmlEeOn_u3QK8c59g]) (buildStatus: OK, buildState: IN_PROGRESS, label: , buildTimeTaken: -1, buildStartTime: 1384045989179, summary: , ignoreWarnings: true, tags: , deleteAllowed: true, personalBuild: false)

Above you can see the project name , Build defintion name also all the properties that are available via RTC for that particular Build request. For each Build request you have a unique Build Result ID. example: _OxgzAEmlEeOn_u3QK8c59g . You can follow that build request in the logs using that ID. In the above example after the build request is made this value is updated in the build properties and gets transferred to Build Forge with all other build properties. You can see that in the log below.

2013-11-09 20:13:09,940 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - Checking build environment name=value: buildResultUUID=default, action=SET, vartype=STANDARD, mode=NORMAL, include uuid=null
2013-11-09 20:13:09,940 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - Build property value: default
2013-11-09 20:13:09,941 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - buildResultUUID value updated with: _OxgzAEmlEeOn_u3QK8c59g
2013-11-09 20:13:09,941 [ccm: AsynchronousTaskRunner-1 @@ 20:13] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - Updating build environment name=value: buildResultUUID=_OxgzAEmlEeOn_u3QK8c59g, entry uuid=2efe1e520c651000a04da39155845584

The part of the log below shows that the build event were found for the above build request. Notice the UUID is same as buildResultUUID .

2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Found event: [UUID _OxgzAEmlEeOn_u3QK8c59g]
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Build definition: BuildForge_JBE build
    Project name: BF_Project_JBE
    Project uuid: 5d0d75490c601000bdeea3917cfe7cfe
    Host name: localhost
    Secure connection: true
    Port: 3966
    Server key: localhost:3966
    User id: null
    All logs: true
    All logs not passed or skipped: false
    Custom BOM enabled: true
    Num first logs:: 5
    First logs enabled: false
    Num last logs: 5
    Last logs enabled: false
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process event [1] job.started: 2 msecs
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG uildforge.team.internal.service.BuildForgeDataMaps  - Setting last event time for key: 9.142.57.67:3966, eventTime: 1384046840000
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time Spent Filling Map:8
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Event Starting: 0/1
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - rtcEvent: com.buildforge.services.client.dbo.Event[Event[uuid=2efe2e210c6510009844a39154f254f2, type=job.started, state=COMPLETE, timeout=60, targetGeoUuid=null, targetIdentifier=6d3529270c5a10008e9a0000574c574c, errorMessage=null, created=1384046840000, args=[]]]
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - buildKey: 2efe1e570c651000a057a39155845584:9.142.57.67:3966, eventProjectUuid: 5d0d75490c601000bdeea3917cfe7cfe, buildUuid: 2efe1e570c651000a057a39155845584
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Handling job event for: 2efe1e570c651000a057a39155845584:9.142.57.67:3966
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Event type: job.started
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process event [2]job.started: 0 msecs
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Event Done: 0/1
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process event Total: 1/1
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process events: 0 msecs
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process BF server 9.142.57.67:3966: 8 msecs
2013-11-09 20:13:14,200 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Total execution time: 12 msecs



2013-11-09 20:13:29,213 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Found event: [UUID _OxgzAEmlEeOn_u3QK8c59g]
2013-11-09 20:13:29,213 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Build definition: BuildForge_JBE build
    Project name: BF_Project_JBE
    Project uuid: 5d0d75490c601000bdeea3917cfe7cfe
    Host name: localhost
    Secure connection: true
    Port: 3966
    Server key: localhost:3966
    User id: null
    All logs: true
    All logs not passed or skipped: false
    Custom BOM enabled: true
    Num first logs:: 5
    First logs enabled: false
    Num last logs: 5
    Last logs enabled: false
2013-11-09 20:13:29,213 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process event [1] step.started: 3 msecs
2013-11-09 20:13:29,213 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG uildforge.team.internal.service.BuildForgeDataMaps  - Setting last event time for key: 9.142.57.67:3966, eventTime: 1384046845000
2013-11-09 20:13:29,213 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time Spent Filling Map:7
2013-11-09 20:13:29,213 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Event Starting: 0/1
2013-11-09 20:13:29,214 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - rtcEvent: com.buildforge.services.client.dbo.Event[Event[uuid=2efe2f730c651000da38a39154675467, type=step.started, state=COMPLETE, timeout=60, targetGeoUuid=null, targetIdentifier=6d3529270c5a10008e9a0000574c574c, errorMessage=null, created=1384046845000, args=[]]]
2013-11-09 20:13:29,214 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - buildKey: 2efe1e570c651000a057a39155845584:9.142.57.67:3966, eventProjectUuid: 5d0d75490c601000bdeea3917cfe7cfe, buildUuid: 2efe1e570c651000a057a39155845584
2013-11-09 20:13:29,214 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Handling step event for: 3E173720-49A7-11E3-9B80-5FF307A6D77B:2efe1e570c651000a057a39155845584:9.142.57.67:3966
2013-11-09 20:13:29,214 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Event type: step.started
2013-11-09 20:13:29,214 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Step uuid: 3E173720-49A7-11E3-9B80-5FF307A6D77B
2013-11-09 20:13:29,214 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Looking for step activity with label: 001 - Load RTC
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG uildforge.team.internal.service.BuildForgeDataMaps  - Adding step activity, key: 3E173720-49A7-11E3-9B80-5FF307A6D77B:2efe1e570c651000a057a39155845584:9.142.57.67:3966, activityId: com.ibm.team.build.internal.common.model.impl.BuildActivityIdImpl@41d841d8 (internalId: <unset>) (id: _TtNQ8EmlEeOn_u3QK8c59g)
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process event [2]step.started: 55 msecs
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Event Done: 0/1
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process event Total: 1/1
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process events: 55 msecs
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to process BF server 9.142.57.67:3966: 62 msecs
2013-11-09 20:13:29,268 [ccm: AsynchronousTaskRunner-3 @@ 20:13] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Total execution time: 66 msecs

Following the build request in the logs we can identify what really happened to the Build request.

Checking Build engine status from the Engineering Workflow Management (Rational Team Concert) log ( ccm.log or jazz.log )

In the Rational Team Concert logs (ccm.log or jazz.log ) for every loop you will see the active engines being checked for responsiveness:

2013-11-26 05:28:02,200 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - ======================= Starting Chunk ======================
2013-11-26 05:28:02,208 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Starting event poller run task
2013-11-26 05:28:02,242 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73137313 (stateId: [UUID _mZf70E0lEeOCYISFFvIuNA], itemId: [UUID _5pI9YIG6EeKAxNIURYE-1w], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,242 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73327332 (stateId: [UUID _Gw26Kk0lEeOCYISFFvIuNA], itemId: [UUID _B213ME0lEeO0XsBZD738Eg], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,243 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73517351 (stateId: [UUID _LnFpUE0lEeOCYISFFvIuNA], itemId: [UUID _I79fwE0lEeO0XsBZD738Eg], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,243 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73707370 (stateId: [UUID _PJ4amk0lEeOCYISFFvIuNA], itemId: [UUID _MeDtgE0lEeO0XsBZD738Eg], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,617 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG dforge.team.internal.service.BuildForgeDataManager  - Connection returned from pool for key: 9.142.57.67:3966:build:/DDDHXmTmkU=:bfEventPollerThread = com.buildforge.services.client.api.APIClientConnection@180a180a
2013-11-26 05:28:03,107 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - lookupBuildRequestAndRun enter
2013-11-26 05:28:03,107 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildAgentBuildEngineHandles enter
2013-11-26 05:28:03,107 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - queryBuildAgentBuildEngines enter
2013-11-26 05:28:03,107 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getServerQueryService enter
2013-11-26 05:28:03,109 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - queryBuildAgentBuildEngines exit
2013-11-26 05:28:03,109 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildAgentBuildEngineHandles exit
2013-11-26 05:28:03,109 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildEngineFromHandle enter
2013-11-26 05:28:03,109 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getRepositoryItemService enter
2013-11-26 05:28:03,110 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - build engine: com.ibm.team.build.internal.common.model.impl.BuildEngineImpl@aa50aa5 (stateId: [UUID _tcWHoFEDEeOl5Jxe2mcgKg], itemId: [UUID _r7VdUFECEeO0XsBZD738Eg], origin: <unset>, immutable: true) (contextId: [UUID _QbK40ExgEeO0XsBZD738Eg], modified: 2013-11-19 05:16:52.762, workingCopy: <unset>) (mergePredecessor: null, workingCopyPredecessor: <unset>, workingCopyMergePredecessor: <unset>, predecessor: [UUID _X6KYkFEDEeOl5Jxe2mcgKg]) (supportsCancellation: false, engineContactInterval: 0, useTeamScheduler: false, id: Build Agent engine, active: true, description: )
2013-11-26 05:28:03,110 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildEngineFromHandle exit
2013-11-26 05:28:03,110 [ccm: AsynchronousTaskRunner-1 @@ 05:28] DEBUG .team.internal.service.BuildForgeBuildLoopRunnable  - Starting build loop run task.
2013-11-26 05:28:03,110 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildEngineFromHandle enter
2013-11-26 05:28:03,110 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getRepositoryItemService enter
2013-11-26 05:28:03,114 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - build engine: com.ibm.team.build.internal.common.model.impl.BuildEngineImpl@1da31da3 (stateId: [UUID _-RV1MFELEeOl5Jxe2mcgKg], itemId: [UUID _THkSoFELEeO0XsBZD738Eg], origin: <unset>, immutable: true) (contextId: [UUID _QbK40ExgEeO0XsBZD738Eg], modified: 2013-11-19 06:16:01.667, workingCopy: <unset>) (mergePredecessor: null, workingCopyPredecessor: <unset>, workingCopyMergePredecessor: <unset>, predecessor: [UUID _dTHgoFELEeOl5Jxe2mcgKg]) (supportsCancellation: false, engineContactInterval: 0, useTeamScheduler: false, id: Loadrule Build Agent 2, active: true, description: )
2013-11-26 05:28:03,114 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildEngineFromHandle exit
2013-11-26 05:28:03,119 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildEngineFromHandle enter
2013-11-26 05:28:03,119 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getRepositoryItemService enter
2013-11-26 05:28:03,119 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - build engine: com.ibm.team.build.internal.common.model.impl.BuildEngineImpl@32443244 (stateId: [UUID _-R_8gFELEeOl5Jxe2mcgKg], itemId: [UUID _efi3gFELEeO0XsBZD738Eg], origin: <unset>, immutable: true) (contextId: [UUID _QbK40ExgEeO0XsBZD738Eg], modified: 2013-11-19 06:16:01.736, workingCopy: <unset>) (mergePredecessor: null, workingCopyPredecessor: <unset>, workingCopyMergePredecessor: <unset>, predecessor: [UUID _kKUpClELEeOl5Jxe2mcgKg]) (supportsCancellation: false, engineContactInterval: 0, useTeamScheduler: false, id: Loadrule Build Agent 3, active: true, description: )
2013-11-26 05:28:03,119 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildEngineFromHandle exit
2013-11-26 05:28:03,128 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - Is Loadrule Build Agent 3 responsive with creds: null/null
2013-11-26 05:28:03,128 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - testEngineConnection enter
2013-11-26 05:28:03,128 [ccm: AsynchronousTaskRunner-3 @@ 05:28] DEBUG com.ibm.rational.buildforge.buildagent              - getBuildAgentConnectService enter
2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Build definition name: BuildForge_JBE build
2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Processing build definition: BuildForge_JBE build
2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to get build def: 17
2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time to get build defs: 17
2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG uildforge.team.internal.service.BuildForgeDataMaps  - Last event time for key: 9.142.57.67:3966, eventTime: 1385448414000
2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time last checked: 1385448414000, and engine id: BF_engine

In the above output you see that there are 4 build engines added to the handle list by the event poller run task.

2013-11-26 05:28:02,208 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Starting event poller run task
2013-11-26 05:28:02,242 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73137313 (stateId: [UUID _mZf70E0lEeOCYISFFvIuNA], itemId: [UUID _5pI9YIG6EeKAxNIURYE-1w], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,242 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73327332 (stateId: [UUID _Gw26Kk0lEeOCYISFFvIuNA], itemId: [UUID _B213ME0lEeO0XsBZD738Eg], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,243 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73517351 (stateId: [UUID _LnFpUE0lEeOCYISFFvIuNA], itemId: [UUID _I79fwE0lEeO0XsBZD738Eg], origin: <unset>, immutable: <unset>)
2013-11-26 05:28:02,243 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Adding engine handle to list: com.ibm.team.build.internal.common.model.impl.BuildEngineHandleImpl@73707370 (stateId: [UUID _PJ4amk0lEeOCYISFFvIuNA], itemId: [UUID _MeDtgE0lEeO0XsBZD738Eg], origin: <unset>, immutable: <unset>)

To verify which Engine UUIDs belong to which Engine you either search for the UUID in the log or you can get the output of the following URL with Jazz Admin account so that it displays all the engine details from all the Project Areas.

https://HOST:PORT/ccm/resource/virtual/build/engines?_prettyPrint=true

In this output you can check the Engine names and their itemID which is the itemID:UUID reported in the server log. This output also tells you if the engine state is "active" and which build definition it supports.

Now futher in the output of server log you will observe the time mentioned by the event poller for which the Build engine " BF_engine" is checked.

2013-11-26 05:28:03,317 [ccm: AsynchronousTaskRunner-0 @@ 05:28] DEBUG eam.internal.service.BuildForgeEventPollerRunnable  - Time last checked: 1385448414000, and engine id: BF_engine

If you see event poller is not checking the Build engines added to the handle then check for the build engine in Rational Team Concert eclipse client, weather its marked "Active"

Related defect "https://jazz.net/jazz/resource/itemName/com.ibm.team.workitem.WorkItem/282410"

Related topics: Deployment web home, Deployment web home

External links:

• IBM

Additional contributors: ZeeshanChoudhry