TFS 2012 – My warehouse jobs are supposed to be running but show QueuedScheduled

trucks

I just finished a very stressful couple of days.  I was working with a client to upgrade their TFS 2010 installation to TFS 2012.3.  During the process we had a couple of issues to resolve, but one of them was blog-worthy.

The stress came from the fact that if we couldn’t resolve these issues we would have to rollback the entire upgrade to TFS 2010. That would negate two weeks of work and probably have an very unhappy client.

Problem

After getting the customer’s system upgraded we noted that their warehouse wasn’t processing.  Strangely, when we launched the Warehouse Controller Web Service on the App Tier machine we saw that there were lots of jobs that had CurrentRun entries that showed a JobState of QueuedScheduled.

Notice that the Build Warehouse Sync job on Line 26 & 27 is showing a JobProcessingStatus of Idle, but the job’s CurrentRun element on lines 40&41 are showing that the job is running but in a QueuedScheduled JobState.  This makes entirely no sense.  The Job is running but it queued so it’s Idle?

 1: xml version="1.0" encoding="utf-8" ?>
 2: <WarehouseProcessingStatus 
 3:  xmlns:xsd="http://www.w3.org/2001/XMLSchema"
 4:  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 5:  xmlns="http://schemas.microsoft.com/TeamFoundatio...">
 6:  <RequestTimeUtc>2013-08-16T14:01:26.4000423ZRequestTimeUtc>
 7:  <WarehouseProcessingOnlineStatus>StartedWarehouseProcessingOnlineStatus>
 8:  <AnalysisProcessingOnlineStatus>StartedAnalysisProcessingOnlineStatus>
 9:  <JobProcessingStatus>IdleJobProcessingStatus>
 10:  <JobsRunning>0JobsRunning>
 11:  <JobsQueued>6JobsQueued>
 12:  <Instance Name="TEAM FOUNDATION"
 13:  JobProcessingStatus="Idle"
 14:  JobsRunning="0"
 15:  JobsQueued="1">
 16:  <Jobs>
 17:  ...
 18:  Jobs>
 19:  Instance>
 20:  <Collections>
 21:  <Collection Name="DefaultCollection"
 22:  JobProcessingStatus="Idle"
 23:  JobsRunning="0"
 24:  JobsQueued="5">
 25:  <Jobs>
 26:  <Job Name="Build Warehouse Sync" 
 27:  JobProcessingStatus="Idle">
 28:  <LastRun QueueTimeUtc="2013-08-16T01:52:33.423Z"
 29:  ExecutionStartTimeUtc="2013-08-16T02:15:11.017Z"
 30:  EndTimeUtc="2013-08-16T02:15:12.123Z"
 31:  Result="Blocked">
 32:  <ResultMessage>
 33:  [Build Warehouse Sync]: ---> TF221107: Reporting for
 34:  Team Foundation Server cannot execute job Build Warehouse Sync
 35:  for team project collection DefaultCollection because the 
 36:  warehouse is offline. Use the Team Foundation Administration 
 37:  Console to start reporting.
 38:  ResultMessage>
 39:  LastRun>
 40:  <CurrentRun QueueTimeUtc="2013-08-16T13:55:00.45Z" 
 41:  JobState="QueuedScheduled" />
 42:  Job>
 43:  
 44:  ...
 45:  
 46:  <Job Name="Work Item Tracking Warehouse Sync" 
 47:  JobProcessingStatus="Idle">
 48:  <LastRun QueueTimeUtc="2013-08-16T01:52:33.423Z" 
 49:  ExecutionStartTimeUtc="2013-08-16T02:15:11.017Z" 
 50:  EndTimeUtc="2013-08-16T02:15:12.123Z" 
 51:  Result="Blocked">
 52:  <ResultMessage>
 53:  [Work Item Tracking Warehouse Sync]: ---> TF221107: Reporting 
 54:  for Team Foundation Server cannot execute job
 55:  Work Item Tracking Warehouse Sync for team project collection
 56:  DefaultCollection because the warehouse is offline. Use the
 57:  Team Foundation Administration Console to start reporting.
 58:  ResultMessage>
 59:  LastRun>
 60:  <CurrentRun QueueTimeUtc="2013-08-16T13:55:00.45Z" 
 61:  JobState="QueuedScheduled" />
 62:  Job>
 63:  Jobs>
 64:  Collection>
 65:  Collections>
 66: WarehouseProcessingStatus>

Digging a little deeper, we jumped down to the Event Viewer on the App Tier machine. 

In case you are not aware, TFS has it’s own section to collect debugging records. These can be found in the Event Viewer | Applications and Services Logs | Microsoft Team Foundation Server | Debug.

SNAGHTMLfdb988a

One of the Information Debug Logs was showing the following error:

 

 1: Log Name: Microsoft-Team Foundation Server/Debug
 2: Source: Microsoft-Team Foundation Server
 3: Date: 8/16/2013 10:09:10 AM
 4: Event ID: 0
 5: Task Category: This task has debugging events
 6: Level: Error
 7: Keywords: Info Messages
 8: User: DOMAINTFSSERVICE
 9: Computer: TFS.company.local
 10: Description:
 11: TFS Informational message
 12: Event Xml:
 13: <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
 14:  <System>
 15:  <Provider Name="Microsoft-Team Foundation Server" 
 16:  Guid="{81761665-68A4-47D5-8106-F2ED2AA8687B}" />
 17:  <EventID>0EventID>
 18:  <Version>0Version>
 19:  <Level>2Level>
 20:  <Task>1Task>
 21:  <Opcode>10Opcode>
 22:  <Keywords>0x8000000000000001Keywords>
 23:  <TimeCreated SystemTime="2013-08-16T14:09:10.375773800Z" />
 24:  <EventRecordID>13163EventRecordID>
 25:  <Correlation ActivityID="{018C9C58-F800-0003-99AD-5341209ACE01}" />
 26:  <Execution ProcessID="1472" ThreadID="4720" />
 27:  <Channel>Microsoft-Team Foundation Server/DebugChannel>
 28:  <Computer>TFS.company.localComputer>
 29:  <Security UserID="S-1-5-21-827956790-191126496-1124750213-8536" />
 30:  System>
 31:  <UserData>
 32:  <Info TraceId="{00000001-0001-0001-0000-000000000000} " 
 33:  xmlns="http://schemas.microsoft.com/TeamFoundation/2010/Framework">
 34:  <Tracepoint>1600Tracepoint>
 35:  <ServiceHost>{00000000-0000-0000-0000-000000000000}ServiceHost>
 36:  <ContextId>0ContextId>
 37:  <ProcessName>TFSJobAgentProcessName>
 38:  <Username>
 39:  Username>
 40:  <Service>
 41:  Service>
 42:  <Method>
 43:  Method>
 44:  <Area>JobAgentArea>
 45:  <Layer>JobServiceUtilLayer>
 46:  <UserAgent>
 47:  UserAgent>
 48:  <Uri>
 49:  Uri>
 50:  <Path>
 51:  Path>
 52:  <UserDefined>
 53:  UserDefined>
 54:  <Message>
 55:  Attempt #155: System.ArgumentException: An item with the same key 
 56:  has already been added.
 57:  at System.Collections.Generic.Dictionary`2.Insert(TKey key, 
 58:  TValue value, 
 59:  Boolean add)
 60:  at Microsoft.TeamFoundation.Framework.Server
 61:  .TeamFoundationExtensionUtility.LoadExtensionTypeMap[T]
 62:  (String pluginDirectory)
 63:  at Microsoft.TeamFoundation.Framework.Server.JobApplication
 64:  .SetupInternal()
 65:  at Microsoft.TeamFoundation.Framework.Server.JobServiceUtil
 66:  .RetryOperationsUntilSuccessful(RetryOperations operations, 
 67:  Int32 maxTries, 
 68:  Int32& delayOnExceptionSeconds)
 69:  Message>
 70:  Info>
 71:  UserData>
 72: Event>

Notice on lines 37 & 55 – 56 we have the really important info.  The error is thrown by the TFSJobAgent and the problem is that it is trying to load an item with the same key into a Dictionary.

Solution

A quick online search turned up a blog post by Rory Street aptly entitled “TFSJobAgent Error – An item with the same key has already been added” in which he comments that the cause was that he had multiple copies of a custom warehouse adapter in the TFSJobAgent’s PlugIns folder. 

C:Program FilesMicrosoft Team Foundation Server 11.0Application TierTFSJobAgentplugins

When the TFSJobAgent service starts it recursively scans the Plugins folder looking for warehouse adapters (Microsoft’s or custom).  It uses reflection to find all of the assemblies that implement the ITeamFoundationJobExtension interface.  Since I have two copies of the same adapter (with different file names) in the folder, it tries to load them both and the names collide.  Rory had a slightly different configuration. He had copies of his custom warehouse adapter in a subfolder of PlugIns but the effect is the same sine the search is recursive

To clean up the multiple copies of my custom adapter in the PlugIns folder I needed to:

  • Start an elevated command prompt
  • Run: net stop TfsJobAgent
  • Delete the extra custom warehouse adapter DLLs from the Plugins folder (and its children)
  • Run: net start TFSJobAgent

Once that was done I rechecked the Warehouse Controller Web Service and all of my QueuedScheduled jobs were either Running or completed successfully.

Thanks Rory! 🙂

Using the Nugetter CodePlex project with TFS 2012 build throws TF215097 error

Problem

While working with a client recently I came across an issue that I think needs to be better documented.

We were implementing Nuget packaging in their TFS 2012 build process.  I knew from past engagements that the Nugetter project on CodePlex is an excellent way to easily add this activity to an existing build process.

We created the build definition using the NuGetterMultiPkgBuildVersionedTemplate20.xaml build process template. When we ran the build, it failed with the following error

TF215097: An error occurred while initializing a build for build definition
[Build Definition] nuget:
Exception Message: The invocation of the constructor on type
‘TfsBuild.NuGetter.Activities.NuGetterProcess’ that matches the specified
binding constraints threw an exception. (type XamlObjectWriterException)

Exception Stack Trace:
at MS.Internal.Xaml.Runtime.ClrObjectRuntime.CreateInstance(XamlType xamlType,
Object[] args)
at System.Xaml.XamlObjectWriter.Logic_CreateAndAssignToParentStart(
ObjectWriterContext ctx)
at System.Xaml.XamlObjectWriter.WriteStartMember(XamlMember property)
at System.Xaml.XamlServices.Transform(XamlReader xamlReader, XamlWriter xamlWriter,
Boolean closeWriter)
at System.Activities.XamlIntegration.FuncFactory`1.Evaluate()
at System.Activities.DynamicActivity.OnInternalCacheMetadata(
Boolean createEmptyBindings)
at System.Activities.Activity.InternalCacheMetadata(Boolean createEmptyBindings,
IList`1& validationErrors)
at System.Activities.ActivityUtilities.ProcessActivity(ChildActivity childActivity,
ChildActivity& nextActivity, Stack`1& activitiesRemaining,
ActivityCallStack parentChain, IList`1& validationErrors,
ProcessActivityTreeOptions options, ProcessActivityCallback callback)
at System.Activities.ActivityUtilities.ProcessActivityTreeCore(
ChildActivity currentActivity, ActivityCallStack parentChain,
ProcessActivityTreeOptions options, ProcessActivityCallback callback,
IList`1& validationErrors)
at System.Activities.ActivityUtilities.CacheRootMetadata(Activity activity,
LocationReferenceEnvironment hostEnvironment, ProcessActivityTreeOptions options,
ProcessActivityCallback callback, IList`1& validationErrors)
at System.Activities.Validation.ActivityValidationServices
.InternalActivityValidationServices.InternalValidate()
at Microsoft.TeamFoundation.Build.Workflow.WorkflowHelpers.ValidateWorkflow(
Activity activity, ValidationSettings validationSettings)
at Microsoft.TeamFoundation.Build.Hosting.BuildProcessCache.LoadFromXaml(
String workflowXaml, TextExpressionImports textExpressionImports)
at Microsoft.TeamFoundation.Build.Hosting.BuildControllerWorkflowManager
.PrepareRequestForBuild(WorkflowManagerActivity activity, IBuildDetail build,
WorkflowRequest request, IDictionary`2 dataContext)
at Microsoft.TeamFoundation.Build.Hosting.BuildWorkflowManager.TryStartWorkflow(
WorkflowRequest request, WorkflowManagerActivity activity,
BuildWorkflowInstance& workflowInstance, Exception& error, Boolean& syncLockTaken)

Inner Exception Details:

Exception Message: Exception has been thrown by the target of an invocation.
(type TargetInvocationException)

Exception Stack Trace:
at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments,
Signature sig, Boolean constructor)
at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj,
Object[] parameters, Object[] arguments)
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr,
Binder binder, Object[] parameters, CultureInfo culture)
at System.Activities.XamlIntegration.ActivityXamlServices.GetXamlSchemaContext(
Assembly assembly, String helperClassName)
at System.Activities.XamlIntegration.ActivityXamlServices.InitializeComponent(
Type componentType, Object componentInstance)
at TfsBuild.NuGetter.Activities.NuGetterProcess.BeforeInitializeComponent(
Boolean& isInitialized)
at TfsBuild.NuGetter.Activities.NuGetterProcess.InitializeComponent()

Inner Exception Details:

Exception Message: Could not load file or assembly ‘System.Management.Automation,
PublicKeyToken=31bf3856ad364e35’ or one of its dependencies.
The system cannot find the file specified. (type FileNotFoundException)

Exception Stack Trace:
at System.Reflection.RuntimeAssembly._nLoad(AssemblyName fileName,
String codeBase, Evidence assemblySecurity, RuntimeAssembly locationHint,
StackCrawlMark& stackMark, IntPtr pPrivHostBinder, Boolean throwOnFileNotFound,
Boolean forIntrospection, Boolean suppressSecurityChecks)
at System.Reflection.RuntimeAssembly.InternalLoadAssemblyName(AssemblyName assemblyRef,
Evidence assemblySecurity, RuntimeAssembly reqAssembly, StackCrawlMark& stackMark,
IntPtr pPrivHostBinder, Boolean throwOnFileNotFound, Boolean forIntrospection,
Boolean suppressSecurityChecks)
at System.Reflection.Assembly.Load(AssemblyName assemblyRef)
at XamlStaticHelperNamespace._XamlStaticHelper.Load(String assemblyNameVal)
at XamlStaticHelperNamespace._XamlStaticHelper.LoadAssemblies()
at XamlStaticHelperNamespace._XamlStaticHelper.get_SchemaContext()

I’ve pasted the entire error message here so that it will be indexed by search engines and thus easier to find. 🙂

Solution

We did a little bit of searching online and followed a few dead-end trails.  We finally tracked down a discussion article on the Nugetter project’s discussion page that pointed to a mismatched PowerShell version on the build controller.

While our build controller machine was running Windows Server 2008 R2, we found that it only had PowerShell v1.0 installed.  We need to have PowerShell v3 installed for this to work.

We installed PowerShell v3 on the build controller and build agent and rebooted both machines.  When we triggered the build again it ran to completion.

I’m not sure if the updated PowerShell was necessary for the Build Agent machine but the client decided to install it anyway.

Synopsis

If you encounter this error, make sure the Build Controller box has PowerShell v3 installed on it.

TFS 2012 Quick Note: How to add text formatting and line breaks to the DEFAULT text of a work item field

This is a quick note so that I can find this in the future. Smileimage

What:

There are times when you want modify a work item so that the value of an HTML string field, like the Description field on a Requirement, has some default value when a new work item is created. You may also want to put some formatting on some or all of this text.

I was working with a customer that wanted to have a “template” for data security that would help the Business Analysts be more consistent in their requirement documentation. We added some bold template text that would be used as a reminder.  The BA would just add the field name and security requirements in plain text next to the defaulted labels.

SNAGHTMLb8342

How:

To get this effect we set the DEFAULT rule on the underlying HTML field to a string of HTML that will get rendered at runtime.  There are two ways that you can enter the HTML to be rendered, through the Process Template Editor or directly within the work item type definition file.  Please note the caveat at the end of this article so you don’t get burned by a limitation of the work item definition schema.

Using the Process Template Editor

When using the Process Template Editor you need to create a DEFAULT rule for your field. In the FROM field select “value” and in the VALUE field you enter your HTML fragment.  In this editor you can enter your HTML just like you would in Visual Studio.  When you hit OK to close the DEFAULT dialog it will escape all of the special characters in the HTML fragment.

SNAGHTML1632e2

Editing the Work Item Type Definition directly

If you edit the work item type definition directly, you have to escape all of the “special” characters so that they don’t interfere with the raw XML surrounding them.  When uploaded to TFS, the escaped entries will be converted to HTML tags that can be rendered at runtime.

 1: <FIELD name="Security" refname="MyCompany.Security" type="HTML">
 2:  <DEFAULT from="value" value="Field Name: 
Security: 

Field Name: 
Security: "
/>
 3: FIELD>

Caveat

There is one thing that really limits the usefulness of this technique.  There is a limit of 255 characters in the value attribute of the DEFAULT element.  This limit is imposed when you import the work item type definition into the team project, so you have to be aware of this when using the Process Template Editor as the text entered there will be escaped on save and could easily go over the character limit.