Pipeline stuck on "Queued" even though runner is online and available?

[#1]

I've got a simple pipeline (mirrors file contents to an FTPS site) which is tied to a Bitbucket Deployment. Pipelines often get stuck on "Queued" without even starting, even though the runner is ready and online.

Here's the tail of the Docker log for the container, after finishing a previous successful build:

[2021-05-05 16:14:56,273] Completing step with result Result{status=PASSED, error=None}.
[2021-05-05 16:14:57,534] Setting runner state to not executing step.
[2021-05-05 16:14:57,535] Waiting for next step.
[2021-05-05 16:15:11,876] Setting runner state to executing step.
[2021-05-05 16:15:19,845] Updating runner state to "ONLINE".
[2021-05-05 16:15:49,844] Updating runner state to "ONLINE".
[2021-05-05 16:16:19,844] Updating runner state to "ONLINE".
[2021-05-05 16:16:49,844] Updating runner state to "ONLINE".
[2021-05-05 16:17:19,844] Updating runner state to "ONLINE".
[2021-05-05 16:17:49,845] Updating runner state to "ONLINE".
[2021-05-05 16:18:19,846] Updating runner state to "ONLINE".
[2021-05-05 16:18:49,845] Updating runner state to "ONLINE".
[2021-05-05 16:19:19,846] Updating runner state to "ONLINE".
[2021-05-05 16:19:49,845] Updating runner state to "ONLINE".
[2021-05-05 16:20:19,846] Updating runner state to "ONLINE".
[2021-05-05 16:20:49,844] Updating runner state to "ONLINE".
[2021-05-05 16:21:19,846] Updating runner state to "ONLINE".
[2021-05-05 16:21:49,844] Updating runner state to "ONLINE".
[2021-05-05 16:22:19,845] Updating runner state to "ONLINE".
[2021-05-05 16:22:49,844] Updating runner state to "ONLINE".
[2021-05-05 16:23:19,845] Updating runner state to "ONLINE".

 If I forcefully stop and start the runner, the pipeline picks it up and runs it right away.

Has anyone else experienced this? Could it be related to the fact I've got a dependency on a Deployment?

[Jorge Cotelo]

I am currently experiencing this issue for about 2 weeks now.

After some time on the "queued" stage I get a `system error`. meanwhile the logs on my docker container shows what you are posting. and I can see the status online not just in the docker logs but also on bitbucket on the repository settings.

I have 3 or 4 schedule task that runs every hour. On a new instance I can manage to have the runner up for about 10 hours and then it goes in that state. when I restart the container it picks up one or two task and hangs there again.

similar thread here: https://community.atlassian.com/t5/Bitbucket-Pipelines-Runners/Runner-stop-responding-when-idle-for-too-long/qaq-p/1662478#U1683450

FYI I am running my container in an AWS EC2 instance

[Andy Gikling]

Bump, same sort of behavior for me.  I have a post about it as well.  Just hangs constantly...

https://community.atlassian.com/t5/Bitbucket-Pipelines-Runners/Pipeline-Hang-During-Checkout/qaq-p/1673959

I would like to test this against basically an empty git repo and see if even the MVP works but then I have to request access again and I keep getting no response lol.  What a joke.

Atlassian, we don't want to do your engineering work.  This product so incredibly alpha it doesn't even appear to work half the time.  I can't believe you have us wasting our time on this.  I'm very frustrated. 

Can we get an engineer in here who knows what they are doing?

UPDATE (same day, silly) : My hang issue appears to be fixed in v1.110.

Thank you.

[lassian]

Hi Jorge,

Can you please provide the UUIDs of the step that was queued so we can investigate why it wasnt scheduled onto the runner.

If the runner is hanging as in the step isnt queued as described on https://community.atlassian.com/t5/Bitbucket-Pipelines-Runners/Runner-stop-responding-when-idle-for-too-long/qaq-p/1662478#U1685713

Can you please raise a support case and provide us the runners logs at the time it was hang and what step was not queued but assigned to it.

Kind Regards,

Nathan Burrell

[Jorge Cotelo]

Hi @lassian  

Here is an example happening this morning I will add the logs for the last step ran:

Last step

[2021-05-06 14:30:35,182] Setting runner state to executing step.
[2021-05-06 14:30:35,186] Getting step StepId{accountUuid={b14cf156-b835-40a8-9fd4-eba8785bb22c}, repositoryUuid={dfc78678-e1b2-4eaf-835c-9adb5687c21b}, pipelineUuid={86d9234b-8ea8-4d3b-b667-77eae971706c}, stepUuid={3a425461-6ab8-4d6f-99a7-2fadbba1429e}}.
[2021-05-06 14:30:35,190] Getting oauth token for step.
[2021-05-06 14:30:35,196] Getting environment variables for step.
[2021-05-06 14:30:35,686] Getting all artifacts for step.
[2021-05-06 14:30:36,023] Setting up directories.
[2021-05-06 14:30:36,023] Starting log uploader.
[2021-05-06 14:30:36,036] Removing container clone
[2021-05-06 14:30:36,044] Removing container build
[2021-05-06 14:30:36,051] Setting up step timeout: PT2H
[2021-05-06 14:30:36,052] Starting websocket listening to STEP_COMPLETED events.
[2021-05-06 14:30:36,054] Checking for step completion every PT30S seconds.
[2021-05-06 14:30:36,151] Updating step progress to PULLING_IMAGES.
[2021-05-06 14:30:36,478] Pulling image docker-public.packages.atlassian.com/sox/atlassian/bitbucket-pipelines-dvcs-tools:prod-stable.
[2021-05-06 14:30:36,603] Pulling image python:3.7.
[2021-05-06 14:30:36,837] Pulling image docker-public.packages.atlassian.com/sox/atlassian/bitbucket-pipelines-auth-proxy:prod-stable.
[2021-05-06 14:30:36,958] Pulling image google/pause:latest.
[2021-05-06 14:30:37,027] Appending log line to main log.
[2021-05-06 14:30:37,086] Removing container pause
[2021-05-06 14:30:37,089] Updating step progress to CLONING.
[2021-05-06 14:30:37,092] Creating container pause.
[2021-05-06 14:30:37,165] Starting container.
[2021-05-06 14:30:37,399] Generating clone script.
[2021-05-06 14:30:37,404] Creating container clone.
[2021-05-06 14:30:37,404] Executing clone script in clone container.
[2021-05-06 14:30:37,504] Starting container.
[2021-05-06 14:30:38,020] Removing container system-auth-proxy
[2021-05-06 14:30:38,023] Creating container system-auth-proxy.
[2021-05-06 14:30:38,106] Starting container.
[2021-05-06 14:30:38,362] Adding container log: /var/lib/docker/containers/3fad9373c176e64c8a26b56aaaf73b1614b1515a8cbc98e6191bd70821f84544/3fad9373c176e64c8a26b56aaaf73b1614b1515a8cbc98e6191bd70821f84544-json.log
[2021-05-06 14:30:38,362] Waiting on container to exit.
[2021-05-06 14:30:38,363] Creating exec into container.
[2021-05-06 14:30:38,369] Starting exec into container and waiting for exec to exit.
[2021-05-06 14:30:38,804] Adding container log: /var/lib/docker/containers/834d08b9f29c88ac3bcd0b8ef9afbef43d1585a9b98cc7ebdf70a1eca98ac17a/834d08b9f29c88ac3bcd0b8ef9afbef43d1585a9b98cc7ebdf70a1eca98ac17a-json.log
[2021-05-06 14:30:38,804] Waiting on container to exit.
[2021-05-06 14:30:39,029] Appending log line to main log.
[2021-05-06 14:30:39,040] Appending log line to log: {c57c4929-6e21-48de-80f4-614da07ffa4d}.
[2021-05-06 14:30:57,896] Container has state (exitCode: Some(0), OOMKilled Some(false))
[2021-05-06 14:30:57,897] Not downloading artifacts. (artifactsDownloadEnabled: true, numberOfArtifacts: 0)
[2021-05-06 14:30:57,897] Updating step progress to DOWNLOADING_CACHES.
[2021-05-06 14:30:58,022] Getting content uri for cache.
[2021-05-06 14:30:58,038] Appending log line to main log.
[2021-05-06 14:30:58,310] Downloading data from media.
[2021-05-06 14:30:59,035] Appending log line to main log.
[2021-05-06 14:30:59,068] Inspecting image python:3.7.
[2021-05-06 14:30:59,082] Container has state (exitCode: Some(0), OOMKilled Some(false))
[2021-05-06 14:30:59,083] Updating step progress to BUILDING.
[2021-05-06 14:30:59,414] Generating build script.
[2021-05-06 14:30:59,429] Container has state (exitCode: Some(0), OOMKilled Some(false))
[2021-05-06 14:30:59,431] Creating container build.
[2021-05-06 14:30:59,431] Executing build script in build container.
[2021-05-06 14:30:59,508] Starting container.
[2021-05-06 14:31:00,028] Appending log line to main log.
[2021-05-06 14:31:00,037] Adding container log: /var/lib/docker/containers/feff25bf0321ebd0038d1f9c2fd91a65fc4524a62019b2ed2d3f5c07a1ee769b/feff25bf0321ebd0038d1f9c2fd91a65fc4524a62019b2ed2d3f5c07a1ee769b-json.log
[2021-05-06 14:31:00,039] Waiting on container to exit.
[2021-05-06 14:31:00,043] Creating exec into container.
[2021-05-06 14:31:00,046] Starting exec into container and waiting for exec to exit.
[2021-05-06 14:31:01,028] Appending log line to main log.
[2021-05-06 14:31:03,029] Appending log line to main log.
[2021-05-06 14:31:04,032] Appending log line to main log.
[2021-05-06 14:31:05,031] Appending log line to main log.
[2021-05-06 14:31:05,058] Updating runner state to "ONLINE".
[2021-05-06 14:31:07,032] Appending log line to main log.
[2021-05-06 14:31:07,164] Container has state (exitCode: Some(0), OOMKilled Some(false))
[2021-05-06 14:31:07,168] Removing container build
[2021-05-06 14:31:07,242] Updating step progress to UPLOAD_CACHES.
[2021-05-06 14:31:07,558] Updating step progress to UPLOADING_ARTIFACTS.
[2021-05-06 14:31:07,888] Creating upload.
[2021-05-06 14:31:08,028] Appending log line to main log.
[2021-05-06 14:31:08,245] Uploading data to media.
[2021-05-06 14:31:08,646] Creating artifact from upload.
[2021-05-06 14:31:09,099] Updating step progress to PARSING_TEST_RESULTS.
[2021-05-06 14:31:09,446] Test report processing complete.
[2021-05-06 14:31:09,446] Removing container clone
[2021-05-06 14:31:09,462] Removing container clone
[2021-05-06 14:31:09,464] Removing container build
[2021-05-06 14:31:09,469] Removing container system-auth-proxy
[2021-05-06 14:31:09,658] Removing container pause
[2021-05-06 14:31:09,938] Updating step progress to COMPLETING_LOGS.
[2021-05-06 14:31:10,027] Appending log line to main log.
[2021-05-06 14:31:10,067] Shutting down log uploader.
[2021-05-06 14:31:10,412] Tearing down directories.
[2021-05-06 14:31:10,420] Cancelling timeout
[2021-05-06 14:31:10,421] Completing step with result Result{status=PASSED, error=None}.
[2021-05-06 14:31:10,768] Setting runner state to not executing step.
[2021-05-06 14:31:10,768] Waiting for next step.
[2021-05-06 14:31:28,088] Setting runner state to executing step.
[2021-05-06 14:31:35,054] Updating runner state to "ONLINE".
[2021-05-06 14:32:05,055] Updating runner state to "ONLINE".
[2021-05-06 14:32:35,054] Updating runner state to "ONLINE"  

there is now another step stock on queue state in the web interface. unfortunately I don't see the UUID of this step in the log of the runner because is not getting there.

Can you provide me with a way to get this UUID so I can check it? an API endpoint?

thanks

[Jorge Cotelo]

I forgot to add after around 2 hours in the queue state I get a system error from the pipeline:

[lassian]

Hi,

As mentioned https://community.atlassian.com/t5/Bitbucket-Pipelines-Runners/Runner-stop-responding-when-idle-for-too-long/qaq-p/1662478#M66

I have just released a patch that should fix the hanging bug.

Please upgrade the runner and ensure you are running 1.133.

Kind Regards,
Nathan Burrell

[Jorge Cotelo]

Thank you @lassian  I will keep testing today and keep the team posted.

[Chad Gilbert]

Thanks, @lassian. I've run a few builds now and the hanging seems to be fixed!

[Artsiom Zhurbila]

@lassian hi! Do you plan to release support of measure how much time pipeline step was in "Queued" status?
Ideally has ability to get history of previous bitbucket pipeline steps and fetch time period in "queued" state

[Meher Gara]

Hello, 

I have this same problem (today 25th of January 2023), trying the external runners for the first time I encountered this problem yesterday, I did the workaround by deleting the runner a recreating it ... but this is tbh is annoying.

Now, I tried the workaround a couple of times still there was no luck, I even deleted the Workspace runner and moved it to the repository as I judged that this is not suitable to be shared in the workspace as it's not reliable.

Here is the uuid of the step: 36920641-216d-4f3f-92ac-a1090af8fceb
( I just copied it from the URL) 

I can provide more info 

Thanks

Please find below the logs if my runner: 

[2023-01-25 15:42:36,972] Runner version: 1.397
[2023-01-25 15:42:36,995] Runner runtime: linux-docker
[2023-01-25 15:42:38,758] Copying Docker cli to working directory.
[2023-01-25 15:42:39,003] Starting websocket listening to RUNNER_UPDATED events.
[2023-01-25 15:42:39,098] Updating runner status to "ONLINE" and checking for new steps assigned to the runner after 0 seconds and then every 30 seconds.
[2023-01-25 15:42:39,267] Updating runner state to "ONLINE".
[2023-01-25 15:43:09,101] Updating runner state to "ONLINE".
[2023-01-25 15:43:39,100] Updating runner state to "ONLINE".
[2023-01-25 15:44:09,101] Updating runner state to "ONLINE".
[2023-01-25 15:44:39,101] Updating runner state to "ONLINE".
[2023-01-25 15:45:09,101] Updating runner state to "ONLINE".
[2023-01-25 15:45:39,100] Updating runner state to "ONLINE".
[2023-01-25 15:46:09,101] Updating runner state to "ONLINE".
[2023-01-25 15:46:39,100] Updating runner state to "ONLINE".
[2023-01-25 15:47:09,100] Updating runner state to "ONLINE".
[2023-01-25 15:47:39,100] Updating runner state to "ONLINE".
[2023-01-25 15:48:09,100] Updating runner state to "ONLINE".
[2023-01-25 15:48:39,100] Updating runner state to "ONLINE".
[2023-01-25 15:49:09,100] Updating runner state to "ONLINE".
[2023-01-25 15:49:39,100] Updating runner state to "ONLINE".

(Brand new Runner :D )