Skip to main content

TFS 2018–TFVC_RepositoryCodeIndexing Job Failing

Back from Holliday with a sequel for my last post. To quickly summarize our problem, we noticed very long wait times before jobs executed by the TFSJobAgent where executed. Things like triggering builds or releases, sending notifications and emails took hours before they got executed.

Will diving into the TFS administration pages, we identified the TFVC_RepositoryCodeIndexing jobs used for search as the root cause of the issue.

Let’s drill deeper into the problem by looking at a specific job log:

Events (46099) completed with status FailedAndRetry. Event 46099 completed with message 'Patch-PeriodicCatchUp: Code patch operation for Repository Id 96f8a036-54bc-47dc-9c37-08fc23d4a07b failed with error Error code -----> MaxAcceptableFractionOfFailedItemsInCrawlerThresholdBreached Exception message -----> Could not download content of lots of files, hence failing this Job. Failed Items Count: 38, Total Items: 38. Exception type -----> Microsoft.VisualStudio.Services.Search.Common.CrawlerException Exception source -----> Microsoft.VisualStudio.Services.Search.Crawler Stack trace, at Microsoft.VisualStudio.Services.Search.Crawler.Definitions.AbstractCrawler.ThrowIfFailedCrawlItemsBreachThreshold(Int32 failedRecordsCount, Int32 totalItemsToBeCrawled) at Microsoft.VisualStudio.Services.Search.Crawler.Extensions.Code.Tfvc.TfvcPatchHttpCrawler.TfvcCodeTraverser(TfvcPatchIndexCrawlSpec crawlSpec, TfvcHttpClientWrapper tfvcHttpWrapper, CrawlSinkParams crawlSinkParams) at Microsoft.VisualStudio.Services.Search.Crawler.Definitions.AbstractCrawler.Run(IndexingExecutionContext indexingExecutionContext) --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at Microsoft.VisualStudio.Services.Search.Crawler.Definitions.AbstractCrawler.Run(IndexingExecutionContext indexingExecutionContext) at Microsoft.VisualStudio.Services.Search.Server.Jobs.Operations.SingleStageCPF.ExecutePipeline(PipelineContext pipelineContext, StringBuilder resultMessage, BookkeepOperation bookkeepOp) at Microsoft.VisualStudio.Services.Search.Server.Jobs.Operations.SingleStageCPF.Run(PipelineContext pipelineContext, StringBuilder resultMessage) --- End of stack trace from previous location where exception was thrown --- at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw() at Microsoft.VisualStudio.Services.Search.Server.Jobs.Operations.SingleStageCPF.Run(PipelineContext pipelineContext, StringBuilder resultMessage) at Microsoft.VisualStudio.Services.Search.Server.Jobs.Operations.Code.RepositoryCodeIndexingOperation.ExecuteCrawlerParserAndFeeder(PipelineContext pipelineContext, StringBuilder resultMessage) at Microsoft.VisualStudio.Services.Search.Server.Jobs.Operations.Code.RepositoryCodePatchOperation.RunOperation(IndexingExecutionContext indexingExecutionContext) [Crawler phase Total items crawled = 0. Time Taken = 15962320ms for Crawl spec type 'Microsoft.VisualStudio.Services.Search.Crawler.CrawlSpecs.TfvcPatchIndexCrawlSpec', Crawler extension 'Microsoft.VisualStudio.Services.Search.Crawler.Extensions.Code.Tfvc.TfvcPatchHttpCrawler'. ]'. OnPremiseTelemetryProperties :{"TFS.Search.Indexing.ParentCorrelationId":"5e7dfff9-485c-42ad-9101-8a258f530276","TFS.Search.Indexing.CorrelationId":"c911ee0a-2001-43fb-987d-96bb4bb8d826","TFS.Search.Indexing.CollectionName":"DefaultCollection","TFS.Search.Indexing.CollectionId":"ce06fba0-ec2f-466a-8569-1e9a13789614","TFS.Search.Indexing.ProjectName":"Ner","TFS.Search.Indexing.ProjectId":"96f8a036-54bc-47dc-9c37-08fc23d4a07b","TFS.Search.Indexing.ProjectIndexingUnitId":"144","TFS.Search.Indexing.RepositoryName":"$/Ner","TFS.Search.Indexing.RepositoryId":"96f8a036-54bc-47dc-9c37-08fc23d4a07b","TFS.Search.Indexing.RepositoryIndexingUnitId":"145","TFS.Search.Indexing.CrawlerServiceFailure":"1","TFS.Search.Indexing.CrawlerServiceFailureReason":"Microsoft.VisualStudio.Services.Search.Common.CrawlerException","TFS.Search.Indexing.CrawlingTime":"15962320","TFS.Search.Indexing.OperationStatus":"Failed","TFS.Search.Indexing.EntityType":"Code","TFS.Search.Indexing.IndexingUnitType":"TFVC_Repository","TFS.Search.Indexing.ChangeType":"Patch","TFS.Search.Indexing.JobExecutionTime":"15962332"}

We were able to see the specific items that failed to index by executing the following query on the collection databases:

select [IndexingUnitId] from [<collection_db>].[Search].[tbl_IndexingUnit] where TFSEntityId like ‘96f8a036-54bc-47dc-9c37-08fc23d4a07b’

select * from [<collection_db>].[Search].[tbl_ItemLevelFailures] where IndexingUnitId = <IndexingUnitId fetched above>

Unfortunately this didn’t bring us any closer to a solution.

In the end we choose the most drastic approach, removed the Search extensions from all collections and removed ElasticSearch itself(https://bartwullems.blogspot.com/2017/11/tfs-2018-remove-elasticsearch.html).

After everything was removed, we reinstalled ElasticSearch, added the Search extensions again and this time everything seemed to work…

Popular posts from this blog

Podman– Command execution failed with exit code 125

After updating WSL on one of the developer machines, Podman failed to work. When we took a look through Podman Desktop, we noticed that Podman had stopped running and returned the following error message: Error: Command execution failed with exit code 125 Here are the steps we tried to fix the issue: We started by running podman info to get some extra details on what could be wrong: >podman info OS: windows/amd64 provider: wsl version: 5.3.1 Cannot connect to Podman. Please verify your connection to the Linux system using `podman system connection list`, or try `podman machine init` and `podman machine start` to manage a new Linux VM Error: unable to connect to Podman socket: failed to connect: dial tcp 127.0.0.1:2655: connectex: No connection could be made because the target machine actively refused it. That makes sense as the podman VM was not running. Let’s check the VM: >podman machine list NAME         ...

Cache stampede: when our cache turned against us

While investigating some performance issues, we ran into an ASP.NET Core API that cached a fairly expensive aggregation query for 60 seconds. Under normal load, that was fine: one request rebuilds the cache, everyone else reads from it. Under peak load, dozens of requests would arrive in that same expiry window, all see a cache miss, and all fire the same expensive query in parallel. The database didn't like that. That was the moment when our caching layer stopped helping and started hurting. A burst of requests comes in at the same time, all miss the cache, and all go hammer the database or the downstream API at once. That's a cache stampede . The cache was supposed to protect our backend, and for a few hundred milliseconds it did the opposite. Why this happens IMemoryCache.GetOrCreate (and its async sibling) looks like it protects you, but it doesn't add any locking on its own. Look at the naive version: public async Task<Report> GetReportAsync(string key) ...

A complex system designed from scratch never works

A few years ago, I worked as an architect on a big mainframe rewrite. I still count it as one of my failures. Not because the technology was wrong, but because I couldn't convince the management team to simplify the approach. Years later, the organization is still struggling to get the new system up and running. I left the project at the time, because I couldn't put my name behind an approach that would take very long and cost a lot of money without a working system to show for it along the way. Gall’s Law That memory keeps coming back to me, because it's a textbook case of Gall's Law playing out in real life. Gall's Law , from John Gall's Systemantics , states it plainly: A complex system that works is invariably found to have evolved from a simple system that worked. A complex system designed from scratch never works, and it cannot be patched to make it work. You have to start over with a simple system that works. What does that mean in practice,...