Skip to content

Merge queue #330

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open

Conversation

Sakib25800
Copy link
Contributor

This PR adds the complete merge queue process from auto build -> merge to master.

The merge queue works like so:

  • Every 30s handle_merge_queue(...) is called
  • It selects a PR that can be merged (based on a set of merge queue priority rules)
  • As part of the sorts, successful auto builds come first and pending ones second and a bunch of other rules. But those are
    the two most important.
  • If handle_merge_queue(...) sees:
    • Successful auto build, it will merge it
    • Pending auto build, it will halt the queue until the auto build is done (to prevent simultaneous auto builds)
  • From the check suite completed webhook, we attempt to try_complete_build(...) where we attempt to determine the build status and post relevant comments

Homu works in exactly the same way, with the only difference being that we use the GitHub checks API rather than the the commit status API.

@Sakib25800
Copy link
Contributor Author

Sakib25800 commented Jun 29, 2025

I wanted this PR to be smaller, e.g. not including the merge to master logic in it, but this wasn’t possible as it would leave the merge queue broken (it would have been left running in a loop of the same PR). Same thing with check runs.

Also, I did have to make two commits where I backtracked:

  • Switching from commit status -> check run
  • Dealing with outdated base branch error (I made some changes and realised this wasn't possible anymore)

I ran the merge queue so many times (nearly ≈200 automated PRs - in separate batches) and somehow got hit a new race condition or bug basically every time, which is why this took so long even though most of the code was written prior.

I initially used the commit statuses API, but I kept consistently running into a situation where there were fewer workflows than checks (which triggered that early exit race condition). I believe this has something to do with GitHub Apps that have check suite write permission being counted as another check suite? I'm not actually sure about this, but in my test repo, I had five apps installed (unintentionally), and I saw five checks and the same number of workflows every time. Switching from commit status to the modern checks API fixed this. TBH, the checks API is the new and improved API with much more gradual and cooler features.

@Sakib25800 Sakib25800 changed the title Merge queue process Merge queue Jun 30, 2025
Copy link
Member

@Kobzol Kobzol left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you! It's clear that you spent a lot of time on this. I haven't yet thought about the full merge process completely (I think there are some race conditions that we will still need to handle), but I went through the individual commits and left a bunch of drive-by comments.

Could you please create a separate PR the commit statuses first? That's useful also for try builds, and it should be a self-contained piece of logic that we could land before the actual merge queue.

I also don't think that we need all the labels that you created. As far as I know, we currently only use "merged-by-bors" when the PR is actually merged, and "waiting-for-bors" when the PR is approved and checks for an auto build to (start and) finish. Then after the auto build completes, the PR is either merged, or it's marked as a failure, and "waiting-for-bors" is removed on both cases.

@@ -46,8 +61,98 @@ pub async fn handle_merge_queue(ctx: Arc<BorsContext>) -> anyhow::Result<()> {
}
}
}

// No build exists for this PR - start a new auto build.
match start_auto_build(&repo, pr).await {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: we have to check a bunch of things here before we decide that the PR is mergeable.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The get_merge_queue_prs(...) retrieves only the PRs eligible for merge so by that point we should have a PR that is considered mergeable.

@@ -115,7 +125,44 @@ async fn start_auto_build(
.await?
{
MergeResult::Success(merge_sha) => {
todo!("Deal with auto build merge success");
// 2. Push merge commit to `AUTO_BRANCH_NAME` where CI runs
client
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Remark: could we unify this code with try builds? It does essentially the same. Perhaps in a future PR, if it makes sense.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I'll do that in a future PR.

}
};

continue;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: we have to handle the rollup race condition here somehow (doesn't need to happen in this PR). As the simplest option we could probably just ask GH about the state of the PR right before trying to merge it.

@Sakib25800
Copy link
Contributor Author

To reduce the size of this PR, I'm going to open a separate PR that only adds the merge queue skeleton - that is, the merge queue process and refresh event. I'll also update the docs in that PR about how the merge queue works as well.

@Sakib25800 Sakib25800 force-pushed the merge-queue-process branch 2 times, most recently from 7e61fb1 to d47d6e0 Compare July 15, 2025 16:13
@Sakib25800 Sakib25800 marked this pull request as ready for review July 17, 2025 11:06
@Sakib25800 Sakib25800 force-pushed the merge-queue-process branch from d47d6e0 to fc3163c Compare July 20, 2025 14:13
Copy link
Member

@Kobzol Kobzol left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you! It seems to work well. There are definitely some things we still need to think about regarding potential failures, but it already is usable.

I would like to see also ordering tests, but it doesn't need to happen in this PR. Left a few nits, but otherwise happy to merge in the current state.

.check_added_labels(&[]);

tester.workflow_full_failure(tester.auto_branch()).await?;
tester
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

workflow_full_failure does not wait until the webhook is processed, so pr.auto_build.as_ref().unwrap() can panic if there is a race. I would wait for the comment and only then check if the auto build was actually created (albeit that should IMO be a separate test, here we care about the labels).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I added the build status failure in the db as a separate test as auto_build_fails_in_db - I forgot to initially.

The test is very flaky when it's like so:

tester.workflow_full_failure(tester.auto_branch()).await?;
tester.expect_comments(1).await;

so I added

tester
    .wait_for_default_pr(|pr| {
        pr.auto_build.as_ref().unwrap().status == BuildStatus::Failure
    })
    .await?;

But I'm not sure why first piece of code is flaky?

thread 'bors::handlers::workflow::tests::auto_build_failed_labels' panicked at src/github/server.rs:353:9:
Handler failed: channel closed
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

thread 'bors::handlers::workflow::tests::auto_build_failed_labels' panicked at src/tests/mocks/bors.rs:89:35:
Bors service has failed: task 3271 panicked with message "Handler failed: channel closed"

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, that looks weird, could you send me the whole test please?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

auto_build_failed_labels test output
running 1 test
2025-07-21T11:30:25.273027Z  INFO auto_build_failed_labels: bors::github::api: Found repository rust-lang/borstest
2025-07-21T11:30:25.273088Z  INFO auto_build_failed_labels: bors::permissions: Reloading permissions for repository rust-lang/borstest
2025-07-21T11:30:25.275332Z TRACE auto_build_failed_labels: bors::utils::timing: Starting operation operation="network_request:load_config"
2025-07-21T11:30:25.276405Z TRACE auto_build_failed_labels: bors::utils::timing: Operation completed successfully operation="network_request:load_config" attempt=0 duration_ms="1.04"
2025-07-21T11:30:25.276423Z  INFO auto_build_failed_labels: bors::github::api: Loaded repository config for rust-lang/borstest: RepositoryConfig { timeout: 3600s, labels: {AutoBuildFailed: [Add("foo"), Add("bar"), Remove("baz")]}, labels_blocking_approval: [], min_ci_time: None, merge_queue_enabled: true }
2025-07-21T11:30:25.276580Z TRACE auto_build_failed_labels: bors::utils::timing: Starting operation operation="db_query:insert_repository_if_not_exists"
2025-07-21T11:30:25.278567Z TRACE auto_build_failed_labels: bors::utils::timing: Operation completed operation="db_query:insert_repository_if_not_exists" duration_ms="1.99"
2025-07-21T11:30:25.429481Z TRACE auto_build_failed_labels: bors::github::webhook: Webhook: event_type `issue_comment`, payload
{"repository":{"id":1,"name":"borstest","url":"https://github.com/rust-lang/borstest","owner":{"login":"rust-lang","id":1001,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/rust-lang","html_url":"https://github.com/rust-lang","followers_url":"https://api.github.com/users/rust-lang/followers","following_url":"https://api.github.com/users/rust-lang/following%7B/other_user%7D","gists_url":"https://api.github.com/users/rust-lang/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/rust-lang/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/rust-lang/subscriptions","organizations_url":"https://api.github.com/users/rust-lang/orgs","repos_url":"https://api.github.com/users/rust-lang/repos","events_url":"https://api.github.com/users/rust-lang/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/rust-lang/received_events","type":"User","site_admin":false}},"action":"created","issue":{"id":1,"node_id":"1","url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","repository_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","labels_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","comments_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","events_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","html_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","number":1,"state":"open","state_reason":null,"title":"PR #1","body":null,"body_text":null,"body_html":null,"user":{"login":"default-user","id":101,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/default-user","html_url":"https://github.com/default-user","followers_url":"https://api.github.com/users/default-user/followers","following_url":"https://api.github.com/users/default-user/following%7B/other_user%7D","gists_url":"https://api.github.com/users/default-user/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/default-user/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/default-user/subscriptions","organizations_url":"https://api.github.com/users/default-user/orgs","repos_url":"https://api.github.com/users/default-user/repos","events_url":"https://api.github.com/users/default-user/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/default-user/received_events","type":"User","site_admin":false},"labels":[],"assignees":[],"author_association":"OWNER","locked":false,"comments":0,"pull_request":{"url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","html_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","diff_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","patch_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1"},"created_at":"2025-07-21T11:30:25.428206Z","updated_at":"2025-07-21T11:30:25.428206Z"},"comment":{"author_association":"OWNER","id":1,"node_id":"1","url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","html_url":"https://github.com/rust-lang/borstest/pull/1#issuecomment-1","body":"@bors r+","body_text":"@bors r+","body_html":"@bors r+","user":{"login":"default-user","id":101,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/default-user","html_url":"https://github.com/default-user","followers_url":"https://api.github.com/users/default-user/followers","following_url":"https://api.github.com/users/default-user/following%7B/other_user%7D","gists_url":"https://api.github.com/users/default-user/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/default-user/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/default-user/subscriptions","organizations_url":"https://api.github.com/users/default-user/orgs","repos_url":"https://api.github.com/users/default-user/repos","events_url":"https://api.github.com/users/default-user/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/default-user/received_events","type":"User","site_admin":false},"created_at":"2025-07-21T11:30:25.428206Z"},"changes":null}
2025-07-21T11:30:25.430562Z TRACE auto_build_failed_labels: bors::github::webhook: Received webhook event Repository(Comment(PullRequestComment { repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, author: GithubUser { id: UserId(101), username: "default-user", html_url: Url { scheme: "https", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("github.com")), port: None, path: "/default-user", query: None, fragment: None } }, pr_number: PullRequestNumber(1), text: "@bors r+", html_url: "https://github.com/rust-lang/borstest/pull/1#issuecomment-1" }))
2025-07-21T11:30:25.430679Z DEBUG auto_build_failed_labels: bors::tests::mocks::bors: Received webhook with status 200 OK and response body ``
2025-07-21T11:30:25.430864Z DEBUG auto_build_failed_labels: bors::github::server: Received repository event: Comment(PullRequestComment { repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, author: GithubUser { id: UserId(101), username: "default-user", html_url: Url { scheme: "https", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("github.com")), port: None, path: "/default-user", query: None, fragment: None } }, pr_number: PullRequestNumber(1), text: "@bors r+", html_url: "https://github.com/rust-lang/borstest/pull/1#issuecomment-1" })
2025-07-21T11:30:25.431202Z DEBUG auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}: bors::bors::handlers: Commands: [Ok(Approve { approver: Myself, priority: None, rollup: None })]
2025-07-21T11:30:25.431219Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}: bors::bors::handlers: Text: @bors r+
2025-07-21T11:30:25.431244Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}: bors::utils::timing: Starting operation operation="network_request:get_pull_request"
2025-07-21T11:30:25.432329Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}: bors::utils::timing: Operation completed successfully operation="network_request:get_pull_request" attempt=0 duration_ms="1.07"
2025-07-21T11:30:25.432379Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}: bors::utils::timing: Starting operation operation="db_query:upsert_pull_request"
2025-07-21T11:30:25.439285Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}: bors::utils::timing: Operation completed operation="db_query:upsert_pull_request" duration_ms="6.91"
2025-07-21T11:30:25.439340Z  INFO auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}:Approve: bors::bors::handlers::review: Approving PR 1
2025-07-21T11:30:25.439441Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}:Approve: bors::utils::timing: Starting operation operation="db_query:approve_pull_request"
2025-07-21T11:30:25.444955Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}:Approve: bors::utils::timing: Operation completed operation="db_query:approve_pull_request" duration_ms="5.50"
2025-07-21T11:30:25.445008Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}:Approve: bors::utils::timing: Starting operation operation="network_request:post_comment"
2025-07-21T11:30:25.445146Z DEBUG auto_build_failed_labels: bors::bors::merge_queue: Processing merge queue
2025-07-21T11:30:25.445202Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:get_repository"
2025-07-21T11:30:25.445475Z DEBUG auto_build_failed_labels: bors::github::server: Received global event: ProcessMergeQueue
2025-07-21T11:30:25.445957Z TRACE auto_build_failed_labels:RepositoryEvent:Comment{pr="rust-lang/borstest#1" author="default-user"}:Approve: bors::utils::timing: Operation completed successfully operation="network_request:post_comment" attempt=0 duration_ms="0.92"
2025-07-21T11:30:25.446091Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:get_repository" duration_ms="0.90"
2025-07-21T11:30:25.446109Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:get_merge_queue_prs"
2025-07-21T11:30:25.448873Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:get_merge_queue_prs" duration_ms="2.76"
2025-07-21T11:30:25.448890Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:get_pull_request"
2025-07-21T11:30:25.449556Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed successfully operation="network_request:get_pull_request" attempt=0 duration_ms="0.66"
2025-07-21T11:30:25.449572Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:get_branch_sha"
2025-07-21T11:30:25.449611Z DEBUG auto_build_failed_labels:MergeQueue: bors::github::api::client: Sending request to /repos/rust-lang/borstest/branches/main
2025-07-21T11:30:25.450113Z DEBUG auto_build_failed_labels:MergeQueue: bors::github::api::client: Received response: Branch { name: "main", commit: CommitObject { sha: "main-sha1", url: Url { scheme: "https", cannot_be_a_base: false, username: "", password: None, host: Some(Domain("github.com")), port: None, path: "/branch/main-main-sha1", query: None, fragment: None } }, protected: false }
2025-07-21T11:30:25.450135Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed successfully operation="network_request:get_branch_sha" attempt=0 duration_ms="0.55"
2025-07-21T11:30:25.450152Z DEBUG auto_build_failed_labels:MergeQueue: bors::bors::merge_queue: Attempting to merge with base SHA main-sha1
2025-07-21T11:30:25.450175Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:set_branch_to_sha"
2025-07-21T11:30:25.450215Z DEBUG auto_build_failed_labels:MergeQueue: bors::github::api::operations: Updating branch /repos/rust-lang/borstest/git/refs/heads/automation/bors/auto-merge to SHA main-sha1
2025-07-21T11:30:25.450872Z TRACE auto_build_failed_labels:MergeQueue: bors::github::api::operations: Updating branch response: status=404 Not Found, text=Ok("")
2025-07-21T11:30:25.451254Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed successfully operation="network_request:set_branch_to_sha" attempt=0 duration_ms="1.07"
2025-07-21T11:30:25.451281Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:merge_branches"
2025-07-21T11:30:25.451576Z TRACE auto_build_failed_labels:MergeQueue: bors::github::api::operations: Response from merging `pr-1-sha` into `automation/bors/auto-merge` in `rust-lang/borstest`: 201 Created ({"sha":"merge-main-sha1-pr-1-sha-0"})
2025-07-21T11:30:25.451595Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed successfully operation="network_request:merge_branches" attempt=0 duration_ms="0.30"
2025-07-21T11:30:25.451608Z DEBUG auto_build_failed_labels:MergeQueue: bors::bors::merge_queue: Merge successful, SHA: merge-main-sha1-pr-1-sha-0
2025-07-21T11:30:25.451618Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:set_branch_to_sha"
2025-07-21T11:30:25.451629Z DEBUG auto_build_failed_labels:MergeQueue: bors::github::api::operations: Updating branch /repos/rust-lang/borstest/git/refs/heads/automation/bors/auto to SHA merge-main-sha1-pr-1-sha-0
2025-07-21T11:30:25.451931Z TRACE auto_build_failed_labels:MergeQueue: bors::github::api::operations: Updating branch response: status=404 Not Found, text=Ok("")
2025-07-21T11:30:25.452256Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed successfully operation="network_request:set_branch_to_sha" attempt=0 duration_ms="0.63"
2025-07-21T11:30:25.452496Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:create_build"
2025-07-21T11:30:25.453135Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:create_build" duration_ms="0.62"
2025-07-21T11:30:25.453162Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:update_pr_auto_build_id"
2025-07-21T11:30:25.453567Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:update_pr_auto_build_id" duration_ms="0.40"
2025-07-21T11:30:25.453810Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:create_check_run"
2025-07-21T11:30:25.454187Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="network_request:create_check_run" duration_ms="0.38"
2025-07-21T11:30:25.454201Z  INFO auto_build_failed_labels:MergeQueue: bors::bors::merge_queue: Created check run 0 for build 1
2025-07-21T11:30:25.454211Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:update_build_check_run_id"
2025-07-21T11:30:25.454814Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:update_build_check_run_id" duration_ms="0.60"
2025-07-21T11:30:25.454829Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="network_request:post_comment"
2025-07-21T11:30:25.455489Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed successfully operation="network_request:post_comment" attempt=0 duration_ms="0.65"
2025-07-21T11:30:25.455506Z  INFO auto_build_failed_labels:MergeQueue: bors::bors::merge_queue: Starting auto build for PR 1
2025-07-21T11:30:25.455535Z DEBUG auto_build_failed_labels: bors::bors::merge_queue: Processing merge queue
2025-07-21T11:30:25.455550Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:get_repository"
2025-07-21T11:30:25.456467Z TRACE auto_build_failed_labels: bors::github::webhook: Webhook: event_type `workflow_run`, payload
{"action":"requested","workflow_run":{"id":1,"workflow_id":1,"node_id":"","name":"Workflow1","head_branch":"automation/bors/auto","head_sha":"merge-main-sha1-pr-1-sha-0","run_number":0,"event":"","status":"","created_at":"1970-01-01T00:00:00Z","updated_at":"1970-01-01T00:00:00Z","url":"https://github.com/workflows/Workflow1/1","html_url":"https://github.com/workflows/Workflow1/1","jobs_url":"https://github.com/workflows/Workflow1/1","logs_url":"https://github.com/workflows/Workflow1/1","check_suite_url":"https://github.com/workflows/Workflow1/1","check_suite_id":1,"artifacts_url":"https://github.com/workflows/Workflow1/1","cancel_url":"https://github.com/workflows/Workflow1/1","rerun_url":"https://github.com/workflows/Workflow1/1","workflow_url":"https://github.com/workflows/Workflow1/1","head_commit":{"id":"","tree_id":"","message":"","timestamp":"1970-01-01T00:00:00Z","author":{"name":"","email":""},"committer":{"name":"","email":""}},"repository":{"id":1,"name":"borstest","url":"https://github.com/rust-lang/borstest","owner":{"login":"rust-lang","id":1001,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/rust-lang","html_url":"https://github.com/rust-lang","followers_url":"https://api.github.com/users/rust-lang/followers","following_url":"https://api.github.com/users/rust-lang/following%7B/other_user%7D","gists_url":"https://api.github.com/users/rust-lang/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/rust-lang/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/rust-lang/subscriptions","organizations_url":"https://api.github.com/users/rust-lang/orgs","repos_url":"https://api.github.com/users/rust-lang/repos","events_url":"https://api.github.com/users/rust-lang/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/rust-lang/received_events","type":"User","site_admin":false}}},"repository":{"id":1,"name":"borstest","url":"https://github.com/rust-lang/borstest","owner":{"login":"rust-lang","id":1001,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/rust-lang","html_url":"https://github.com/rust-lang","followers_url":"https://api.github.com/users/rust-lang/followers","following_url":"https://api.github.com/users/rust-lang/following%7B/other_user%7D","gists_url":"https://api.github.com/users/rust-lang/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/rust-lang/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/rust-lang/subscriptions","organizations_url":"https://api.github.com/users/rust-lang/orgs","repos_url":"https://api.github.com/users/rust-lang/repos","events_url":"https://api.github.com/users/rust-lang/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/rust-lang/received_events","type":"User","site_admin":false}}}
2025-07-21T11:30:25.457177Z TRACE auto_build_failed_labels: bors::github::webhook: Received webhook event Repository(WorkflowStarted(WorkflowRunStarted { repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, name: "Workflow1", branch: "automation/bors/auto", commit_sha: CommitSha("merge-main-sha1-pr-1-sha-0"), run_id: RunId(1), workflow_type: Github, url: "https://github.com/workflows/Workflow1/1" }))
2025-07-21T11:30:25.457222Z DEBUG auto_build_failed_labels: bors::tests::mocks::bors: Received webhook with status 200 OK and response body ``
2025-07-21T11:30:25.457993Z TRACE auto_build_failed_labels: bors::github::webhook: Webhook: event_type `workflow_run`, payload
{"action":"completed","workflow_run":{"id":1,"workflow_id":1,"node_id":"","name":"Workflow1","head_branch":"automation/bors/auto","head_sha":"merge-main-sha1-pr-1-sha-0","run_number":0,"event":"","status":"","conclusion":"failure","created_at":"1970-01-01T00:00:00Z","updated_at":"1970-01-01T00:00:00Z","url":"https://github.com/workflows/Workflow1/1","html_url":"https://github.com/workflows/Workflow1/1","jobs_url":"https://github.com/workflows/Workflow1/1","logs_url":"https://github.com/workflows/Workflow1/1","check_suite_url":"https://github.com/workflows/Workflow1/1","check_suite_id":1,"artifacts_url":"https://github.com/workflows/Workflow1/1","cancel_url":"https://github.com/workflows/Workflow1/1","rerun_url":"https://github.com/workflows/Workflow1/1","workflow_url":"https://github.com/workflows/Workflow1/1","head_commit":{"id":"","tree_id":"","message":"","timestamp":"1970-01-01T00:00:00Z","author":{"name":"","email":""},"committer":{"name":"","email":""}},"repository":{"id":1,"name":"borstest","url":"https://github.com/rust-lang/borstest","owner":{"login":"rust-lang","id":1001,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/rust-lang","html_url":"https://github.com/rust-lang","followers_url":"https://api.github.com/users/rust-lang/followers","following_url":"https://api.github.com/users/rust-lang/following%7B/other_user%7D","gists_url":"https://api.github.com/users/rust-lang/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/rust-lang/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/rust-lang/subscriptions","organizations_url":"https://api.github.com/users/rust-lang/orgs","repos_url":"https://api.github.com/users/rust-lang/repos","events_url":"https://api.github.com/users/rust-lang/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/rust-lang/received_events","type":"User","site_admin":false}}},"repository":{"id":1,"name":"borstest","url":"https://github.com/rust-lang/borstest","owner":{"login":"rust-lang","id":1001,"node_id":"MDQ6VXNlcjQ1MzkwNTc=","avatar_url":"https://avatars.githubusercontent.com/u/4539057?v=4","gravatar_id":"","url":"https://api.github.com/users/rust-lang","html_url":"https://github.com/rust-lang","followers_url":"https://api.github.com/users/rust-lang/followers","following_url":"https://api.github.com/users/rust-lang/following%7B/other_user%7D","gists_url":"https://api.github.com/users/rust-lang/gists%7B/gist_id%7D","starred_url":"https://api.github.com/users/rust-lang/starred%7B/owner%7D%7B/repo%7D","subscriptions_url":"https://api.github.com/users/rust-lang/subscriptions","organizations_url":"https://api.github.com/users/rust-lang/orgs","repos_url":"https://api.github.com/users/rust-lang/repos","events_url":"https://api.github.com/users/rust-lang/events%7B/privacy%7D","received_events_url":"https://api.github.com/users/rust-lang/received_events","type":"User","site_admin":false}}}
2025-07-21T11:30:25.458534Z TRACE auto_build_failed_labels: bors::github::webhook: Received webhook event Repository(WorkflowCompleted(WorkflowRunCompleted { repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, branch: "automation/bors/auto", commit_sha: CommitSha("merge-main-sha1-pr-1-sha-0"), run_id: RunId(1), status: Failure, running_time: Some(TimeDelta { secs: 0, nanos: 0 }), check_suite_id: CheckSuiteId(1) }))
2025-07-21T11:30:25.458566Z DEBUG auto_build_failed_labels: bors::tests::mocks::bors: Received webhook with status 200 OK and response body ``
2025-07-21T11:30:25.458595Z DEBUG auto_build_failed_labels: bors::github::server: Received repository event: WorkflowStarted(WorkflowRunStarted { repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, name: "Workflow1", branch: "automation/bors/auto", commit_sha: CommitSha("merge-main-sha1-pr-1-sha-0"), run_id: RunId(1), workflow_type: Github, url: "https://github.com/workflows/Workflow1/1" })
2025-07-21T11:30:25.458649Z  INFO auto_build_failed_labels:RepositoryEvent:Workflow started{repo="rust-lang/borstest" id=1}: bors::bors::handlers::workflow: Handling workflow started (name=Workflow1, url=https://github.com/workflows/Workflow1/1, branch=automation/bors/auto, commit=merge-main-sha1-pr-1-sha-0)
2025-07-21T11:30:25.458663Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow started{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:find_build"
2025-07-21T11:30:25.458987Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:get_repository" duration_ms="3.44"
2025-07-21T11:30:25.459003Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Starting operation operation="db_query:get_merge_queue_prs"
2025-07-21T11:30:25.459360Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow started{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:find_build" duration_ms="0.70"
2025-07-21T11:30:25.459376Z  INFO auto_build_failed_labels:RepositoryEvent:Workflow started{repo="rust-lang/borstest" id=1}: bors::bors::handlers::workflow: Storing workflow started into DB
2025-07-21T11:30:25.459388Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow started{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:create_workflow"
2025-07-21T11:30:25.460679Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow started{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:create_workflow" duration_ms="1.29"
2025-07-21T11:30:25.460717Z DEBUG auto_build_failed_labels: bors::github::server: Received repository event: WorkflowCompleted(WorkflowRunCompleted { repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, branch: "automation/bors/auto", commit_sha: CommitSha("merge-main-sha1-pr-1-sha-0"), run_id: RunId(1), status: Failure, running_time: Some(TimeDelta { secs: 0, nanos: 0 }), check_suite_id: CheckSuiteId(1) })
2025-07-21T11:30:25.460760Z  INFO auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::bors::handlers::workflow: Updating status of workflow to Failure
2025-07-21T11:30:25.460774Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:update_workflow_status"
2025-07-21T11:30:25.461714Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:update_workflow_status" duration_ms="0.94"
2025-07-21T11:30:25.461731Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:find_build"
2025-07-21T11:30:25.462365Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:find_build" duration_ms="0.63"
2025-07-21T11:30:25.462381Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:find_pr_by_build"
2025-07-21T11:30:25.463619Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:find_pr_by_build" duration_ms="1.24"
2025-07-21T11:30:25.463637Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:get_workflows_for_build"
2025-07-21T11:30:25.464536Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:get_workflows_for_build" duration_ms="0.90"
2025-07-21T11:30:25.464553Z DEBUG auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::bors::handlers::workflow: Workflow runs from DB: [WorkflowModel { id: 1, build: BuildModel { id: 1, repository: GithubRepoName { owner: "rust-lang", name: "borstest" }, branch: "automation/bors/auto", commit_sha: "merge-main-sha1-pr-1-sha-0", status: Pending, parent: "main-sha1", created_at: 2025-07-21T11:30:25.452407Z, check_run_id: Some(0) }, name: "Workflow1", url: "https://github.com/workflows/Workflow1/1", run_id: RunId(1), workflow_type: Github, status: Failure, created_at: 2025-07-21T11:30:25.459707Z }]
2025-07-21T11:30:25.464603Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="db_query:update_build_status"
2025-07-21T11:30:25.465278Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="db_query:update_build_status" duration_ms="0.67"
2025-07-21T11:30:25.465312Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="network_request:add_labels"
2025-07-21T11:30:25.465757Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed successfully operation="network_request:add_labels" attempt=0 duration_ms="0.43"
2025-07-21T11:30:25.465787Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="network_request:remove_labels"
2025-07-21T11:30:25.467171Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed successfully operation="network_request:remove_labels" attempt=0 duration_ms="1.37"
2025-07-21T11:30:25.467201Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="network_request:update_check_run"
2025-07-21T11:30:25.467914Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed operation="network_request:update_check_run" duration_ms="0.72"
2025-07-21T11:30:25.467931Z  INFO auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::bors::handlers::workflow: Build failed for PR 1
2025-07-21T11:30:25.468619Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Starting operation operation="network_request:post_comment"
2025-07-21T11:30:25.469128Z TRACE auto_build_failed_labels:MergeQueue: bors::utils::timing: Operation completed operation="db_query:get_merge_queue_prs" duration_ms="10.12"
2025-07-21T11:30:25.469152Z DEBUG auto_build_failed_labels: bors::bors::merge_queue: Merge queue received shutdown signal
2025-07-21T11:30:25.469428Z TRACE auto_build_failed_labels:RepositoryEvent:Workflow completed{repo="rust-lang/borstest" id=1}: bors::utils::timing: Operation completed successfully operation="network_request:post_comment" attempt=0 duration_ms="0.79"

thread 'bors::handlers::workflow::tests::auto_build_failed_labels' panicked at src/github/server.rs:353:9:
Handler failed: channel closed
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

thread 'bors::handlers::workflow::tests::auto_build_failed_labels' panicked at src/tests/mocks/bors.rs:89:35:
Bors service has failed: task 20 panicked with message "Handler failed: channel closed"
test bors::handlers::workflow::tests::auto_build_failed_labels ... FAILED

failures:

failures:
    bors::handlers::workflow::tests::auto_build_failed_labels

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 257 filtered out; finished in 0.66s

error: test failed, to rerun pass `--lib`

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, you meant the actual test itself.

auto_build_failed_labels
    #[sqlx::test]
    async fn auto_build_failed_labels(pool: sqlx::PgPool) {
        let github = GitHubState::default().with_default_config(
            r#"
merge_queue_enabled = true

[labels]
auto_build_failed = ["+foo", "+bar", "-baz"]
      "#,
        );

        BorsBuilder::new(pool)
            .github(github)
            .run_test(async |tester| {
                tester.post_comment("@bors r+").await?;
                tester.expect_comments(1).await;
                tester.process_merge_queue().await;
                tester.expect_comments(1).await;

                let repo = tester.default_repo();
                repo.lock()
                    .get_pr(default_pr_number())
                    .check_added_labels(&[]);

                tester.workflow_full_failure(tester.auto_branch()).await?;
                tester.expect_comments(1).await;

                let pr = repo.lock().get_pr(default_pr_number()).clone();
                pr.check_added_labels(&["foo", "bar"]);
                pr.check_removed_labels(&["baz"]);

                Ok(())
            })
            .await;
    }
    ```
</details>

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks. The problem is this race condition:

  1. The test sends a workflow failure event
  2. The workflow handler sends a comment to GitHub
  3. The test receives the comment
  4. The test ends and closes the merge queue receiver side
  5. The workflow handler continues, and tries to trigger the merge queue, but it has already been closed in the meantime

We can either send the comment at the very end of the workflow handler, or synchronize in the test to make sure that the workflow event has been fully processed.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks!

.check_added_labels(&[]);

tester.workflow_full_failure(tester.auto_branch()).await?;
tester.wait_for_default_pr(|pr| {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same race condition here.

&commit_sha,
&pr.base_branch,
);
repo.client.post_comment(pr.number, comment).await?;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We should IMO only send the comment once the actual merge has happened. It's better if we merge something and miss a comment than if we send a misleading comment, but the merge doesn't actually happen. I know that homu does it in the opposite order, but this seems better to me. Anyway, let's keep it like this for now, it's not critical, and maybe we should first mirror homu before we make larger behavioral changes here.

}

#[sqlx::test]
async fn auto_build_branch_history(pool: sqlx::PgPool) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be nice to add some ordering tests. So create a bunch of PRs, approve them, then run the merge queue with workflow webhooks a few times and check the branch history to see in which order they were merged.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants