Azure / Azure/azure-sdk-tools

[PR Workflow] Bug: Commits made in rapid succession often lead to GitHub checks being stuck in queued state

Open
#7,321 1 comment 0 reactions 1 assignee Claimed by @konrad-jamrozik View on GitHub
bug Central-EngSys openapi-alps Spec PR Tools
Dominant language
C#
Stars
135
Forks
260
Avg merge
3d 1h
Merged PRs (30d)
143

Description

Consider this PR:
- https://github.com/Azure/azure-rest-api-specs-pr/pull/15148

Before I ran the `/azp run` command [here](https://github.com/Azure/azure-rest-api-specs-pr/pull/15148#issuecomment-1816960225), the GitHub checks were stuck in queued state.

Th last two commits were made in rapid succession at 1:11 AM and 1:14 AM PST, Nov 17, 2023:

![image](https://github.com/Azure/azure-sdk-tools/assets/4429827/f6208b62-cd6d-4f86-9cdb-c96bdef0fbe1)

Taking as an example the `PR Summary` check, we can see:
- [Check run ID 18777934021 corresponding to 1fec022](https://github.com/Azure/azure-rest-api-specs-pr/pull/15148/checks?check_run_id=18777934021), succeeded at 1:17 AM PST
- Backed by [build 3271666 for 1fec022](https://dev.azure.com/azure-sdk/internal/_build/results?buildId=3271666&view=results)
- Corresponds to `unifiedPipelineBuildId` of `2d3c1b9c-b7ab-4c10-a5c1-f39354dd4d62`
- [Check run ID 18777999165 corresponding to 42f4ee3](https://github.com/Azure/azure-rest-api-specs-pr/pull/15148/checks?check_run_id=18777999165)
- Backed by [build 3271673 for 42f4ee3](https://dev.azure.com/azure-sdk/internal/_build/results?buildId=3271673&view=results)
- Corresponds to `unifiedPipelineBuildId` of `86f51f96-58c1-49b6-8da1-3dd8906e92bb`

The openapi-alps logic did successfully compute the latter check of `18777999165` is in `completed` state but it determined there is no need to push that change to the PR in GitHub. The specific Kusto log from the time of `2023-11-17 09:21:08.9544747 UTC` / `2023-11-17 01:21:08.9544747 PST` says:

> processEvent: prUrl: https://github.com/Azure/azure-rest-api-specs-pr/pull/15148, updateUnifiedPipelineDb: **false**, {"env":"prod","source":"github","unifiedPipelineTaskKey":"Summary","unifiedPipelineSubTaskKey":"","unifiedPipelineBuildId":"86f51f96-58c1-49b6-8da1-3dd8906e92bb","pipelineBuildId":"3271673","pipelineJobId":"d6a48a56-e996-55ca-2302-c3a9a7be685b","pipelineTaskId":"","logUrl":"https://dev.azure.com/azure-sdk//internal/_build/results?buildId=3271673&view=logs&j=d6a48a56-e996-55ca-2302-c3a9a7be685b","labels":["ARMChangesRequested","ARMReview","resource-manager","RPaaS","new-api-version","CI-MissingBaseCommit"],"status":"completed","result":"success","subTitle":"","logPath":""}

which was caused by the logic evaluation as captured by the previous log in the same second:

> processUnifiedPipelineRunEvent: prUrl: https://github.com/Azure/azure-rest-api-specs-pr/pull/15148, event.unifiedPipelineTaskKey: Summary, event.status: completed. **Task upBuildId/upTaskKey/upSubTaskKey: 86f51f96-58c1-49b6-8da1-3dd8906e92bb/Summary/ is not equal to latest buildId of pr.currentBuildId: 2d3c1b9c-b7ab-4c10-a5c1-f39354dd4d62. Returning early**.

I analyzed the logs and there does not appear to be any reason for this to happen: the logs denote everything happened in sequence. Specifically, we can see that these logs happened in sequence, at 2023-11-17 09:12:17.7245650 UTC and 2023-11-17 09:14:30.3441131 UTC, over 2 minutes apart:

> '[PipelineBot]: triggerPipeline triggerType: PR: PR: https://github.com/Azure/azure-rest-api-specs-pr/pull/15148: adding following tasks:
(...)
{
"queuedAt": "2023-11-17T09:12:17.409Z",
"env": "prod",
"name": "Summary",
"status": "queued",
"checkRunId": 18777934021,
"checkRunUrl": "https://github.com/Azure/azure-rest-api-specs-pr/pull/15148/checks?check_run_id=18777934021"
},

> '[PipelineBot]: triggerPipeline triggerType: PR: PR: https://github.com/Azure/azure-rest-api-specs-pr/pull/15148: adding following tasks:
(...)
{
"queuedAt": "2023-11-17T09:14:30.037Z",
"env": "prod",
"name": "Summary",
"status": "queued",
"checkRunId": 18777999165,
"checkRunUrl": "https://github.com/Azure/azure-rest-api-specs-pr/pull/15148/checks?check_run_id=18777999165"
}

They are relevant because the log [is emitted](https://devdiv.visualstudio.com/DefaultCollection/DevDiv/_git/openapi-alps?path=private/openapi-kebab/src/bots/pipeline/triggerPipeline.ts&version=GC578520441aa0d67c381202f0d82c9e7d55e4e93f&line=632&lineStartColumn=7&lineEndColumn=125&_a=contents) just after the `unifiedPipelineBuildId` gets updated in the database:

> pipelinePullRequest.currentBuildId = unifiedPipelineBuildId;
> (...)
> await pipelinePullRequestCol!.put(pipelinePullRequest);

Hence the `currentBuildId` should be `86f51f96-58c1-49b6-8da1-3dd8906e92bb` and not `2d3c1b9c-b7ab-4c10-a5c1-f39354dd4d62`.

I submitted following PR to gain more diagnostic logs:
- [Pull Request 511850](https://devdiv.visualstudio.com/DevDiv/_git/openapi-alps/pullrequest/511850): Add logs to debug issues with unifiedPipelineBuildId and pipelinePullRequest.currentBuildId

Kusto query used for investigation: [Web](https://dataexplorer.azure.com/clusters/https%3a%2f%2fazsdkengsys.westus2.kusto.windows.net/databases/Pipelines?query=H4sIAAAAAAAEAJ1WXU%2frRhB9R%2bI%2fbP2SuPV3KIS0VLo3UG5bLiAI6gtStLEn9l4cr7uzTpqqP76ztkOcEITUPFjOztmZMzNnZ%2b377P7h7pKVooRcFODOpGa5TJHNpSITy7QuceT7qdBZNfNiufA%2f%2fVMp8Ll5ugpQu7wULpYQo1sqv6zy3A9%2fDE%2bGx0e%2bz54QktqXKJaEFSnXQhb1ygeuMXlxtZQ5%2bgKxAvTPBlF4fJSDZqW6leyCWXUY66c60CQDNhcKNbOubidXDyyBuShEHU0rkaag7tskLZbxsoSCmHHNEq5BiwX0oyAauGHohmcsOB%2bF0SgYeuHwZBgFJzZ7moyb2Ki50hPCE4H3tgajILDdMCNmcV6hBtXvbbLlCXhUYF7wfK1FjJ6QPlYzjJUoDVn0h3EAQRIGbhwlp%2b5JNBu6szA5d%2bEsHESz03k45AOfCi8rFUOqZFWir1I3loXmlJ2ifpSmFTLx6bEUCSj0FyJWEuVce7IEVTeBUy1QpJlGfyXVC5Y8hs6rSl89GofG3zk%2fj3q2R2nzGUfoWx%2bBLdsbb9Y%2flSW9o8zhhvQ1Hd8cH%2f3LVhkoYKaGU81%2budhW943x507lf2BRtgW8Rrg2tbjlBEfqMDKrq2pru4HiE%2bK7GvLb7a93pCdJiNE7kPu7xwnzWRQE7wB8OgA%2bVXMJNQD%2b1lAk7J52bSUyrXQ81XKay5jn%2fSYnh1lPj%2f49j8VcxJZt9kpF3WKzdb07AYw7Dink70hqvmAlVwjTb%2fSnX%2fOwO6jjI0Y%2fkivh2jDN0tsyEeJQ7Vr8AyxbEL0JJMHsmFtbS8or6G9ruYEl5B1Tbv63ts9VsebFV0w79gWmrfVPEqSWxVdA5GnX%2b6JZ2WZiZHRX6QYyRZM%2fNfEbxJpGUlNEqqBj6uAcSNLZZOew5llzdrb0nD0uTidop9hNImI%2b7wuERanX%2fVcPdndLx7Pd4drheCDmVmzf13JGrWKu%2b9b%2fG8mWU49Nu%2bu1ke9fFVSQWIxTQv0mlPVYLRZcrXcXzRGnxD064eNcQKG9OIP4Bb2qNDK3SL0tVUtRdUA9FaRsSDZzd2zQlm03XdyC98fzvn2sgAZWkTIiMBfpZ8WLOHuD4kliMHOZ53Jl3jTHF7TYK26TRsN2j9vlrMl1Q4n2XgKpJveonlWua4GPWK8tTM%2by3%2filptIAxT3HD1VxtaRa7bgHs%2bJVu8gJxfwD1iO2Kf5OiHr64Yp6%2fhqp9jva7dEgOgtPT0%2b7vaiXzgaWvQP8OMOOi2frMNdna%2fS80cqz1W3tJgxd%2bzQZE0Nfk3cjxQcgxaEeU6PoDJj7WSAr6LuDL4kNn%2bVgMqcr%2fRJoFbD5HqFbyxxipiXTdNUXsDKDshJ54tRfE6tMxFltakTJVkbjqKv4hb49WK9Rea8h4nXO8K3x9Nk4ao%2byOdQ7haM5HZrHIVpN2KRd4gVr1MVW5GClhKYQTNKgItrXQn%2bpZg29LoHrL%2fXBeGo27nH46Mx1uR2aK9vsnN1A746cnSuImxvo%2bOg%2fbLDygycKAAA%3d)

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.