Long wait times to provision a VM in GCP

[rkarasulli]

Jenkins and plugins versions report

Environment

Paste the output here

What Operating System are you using (both controller, and any agents involved in the problem)?

Jenkins: 2.440.3
OS: Linux - 6.5.0-1018-gcp
Java: 17.0.10 - Private Build (OpenJDK 64-Bit Server VM)

Office-365-Connector:4.21.1
Parameterized-Remote-Trigger:3.2.0
ace-editor:1.1
ansicolor:1.0.4
ant:497.v94e7d9fffa_b_9
antisamy-markup-formatter:162.v0e6ec0fcfcf6
apache-httpcomponents-client-4-api:4.5.14-208.v438351942757
artifactory:4.0.6
asm-api:9.7-33.v4d23ef79fcc8
authentication-tokens:1.53.v1c90fd9191a_b_
aws-credentials:231.v08a_59f17d742
aws-java-sdk-ec2:1.12.696-451.v0651a_da_9ca_ec
aws-java-sdk-minimal:1.12.696-451.v0651a_da_9ca_ec
blueocean:1.27.12
blueocean-bitbucket-pipeline:1.27.12
blueocean-commons:1.27.12
blueocean-config:1.27.12
blueocean-core-js:1.27.12
blueocean-dashboard:1.27.12
blueocean-display-url:2.4.2
blueocean-events:1.27.12
blueocean-git-pipeline:1.27.12
blueocean-github-pipeline:1.27.12
blueocean-i18n:1.27.12
blueocean-jwt:1.27.12
blueocean-personalization:1.27.12
blueocean-pipeline-api-impl:1.27.12
blueocean-pipeline-editor:1.27.12
blueocean-pipeline-scm-api:1.27.12
blueocean-rest:1.27.12
blueocean-rest-impl:1.27.12
blueocean-web:1.27.12
bootstrap5-api:5.3.3-1
bouncycastle-api:2.30.1.77-225.v26ea_c9455fd9
branch-api:2.1169.va_f810c56e895
build-blocker-plugin:165.v5ecb_fb_f61520
build-name-setter:2.4.2
build-timeout:1.32
build-timestamp:1.0.3
build-user-vars-plugin:166.v52976843b_435
caffeine-api:3.1.8-133.v17b_1ff2e0599
checks-api:2.2.0
cloudbees-bitbucket-branch-source:886.v44cf5e4ecec5
cloudbees-folder:6.901.vb_4c7a_da_75da_3
command-launcher:107.v773860566e2e
commons-httpclient3-api:3.1-3
commons-lang3-api:3.13.0-62.v7d18e55f51e2
commons-text-api:1.11.0-109.vfe16c66636eb_
conditional-buildstep:1.4.3
config-file-provider:973.vb_a_80ecb_9a_4d0
credentials:1337.v60b_d7b_c7b_c9f
credentials-binding:677.vdc9d38cb_254d
custom-folder-icon:2.12
datadog:7.0.1
date-parameter:0.0.4
description-setter:239.vd0a_6b_785f92d
display-upstream-changes:0.3.2
display-url-api:2.204.vf6fddd8a_8b_e9
docker-commons:439.va_3cb_0a_6a_fb_29
docker-workflow:572.v950f58993843
durable-task:555.v6802fe0f0b_82
echarts-api:5.5.0-1
email-ext:1806.v856a_01a_fa_39a_
envinject:2.908.v66a_774b_31d93
envinject-api:1.199.v3ce31253ed13
environment-script:100.v3a_f1a_6a_b_7549
favorite:2.208.v91d65b_7792a_c
file-parameters:316.va_83a_1221db_a_7
flexible-publish:0.16.1
font-awesome-api:6.5.2-1
generic-webhook-trigger:2.2.1
gerrit-code-review:0.4.9
gerrit-trigger:2.41.1
git:5.2.2
git-client:4.7.0
git-server:117.veb_68868fa_027
github:1.38.0
github-api:1.318-461.v7a_c09c9fa_d63
github-branch-source:1789.v5b_0c0cea_18c3
github-oauth:597.ve0c3480fcb_d0
github-pullrequest:0.7.0
google-compute-engine:4.573.v7dcd6a_37a_ee2
google-oauth-plugin:1.330.vf5e86021cb_ec
gradle:2.11
gson-api:2.10.1-15.v0d99f670e0a_7
handy-uri-templates-2-api:2.1.8-30.v7e777411b_148
htmlpublisher:1.33
hudson-wsclean-plugin:1.0.8
instance-identity:185.v303dc7c645f9
ionicons-api:74.v93d5eb_813d5f
jackson2-api:2.17.0-379.v02de8ec9f64c
jakarta-activation-api:2.1.3-1
jakarta-mail-api:2.1.3-1
javadoc:243.vb_b_503b_b_45537
javax-activation-api:1.2.0-6
javax-mail-api:1.6.2-9
jaxb:2.3.9-1
jdk-tool:73.vddf737284550
jenkins-design-language:1.27.12
jersey2-api:2.42-147.va_28a_44603b_d5
jfrog:1.5.0
jira:3.13
jjwt-api:0.11.5-112.ve82dfb_224b_a_d
jnr-posix-api:3.1.19-2
job-import-plugin:3.6
jobConfigHistory:1229.v3039470161a_d
joda-time-api:2.12.7-29.v5a_b_e3a_82269a_
jquery3-api:3.7.1-2
jsch:0.2.16-86.v42e010d9484b_
json-api:20240303-41.v94e11e6de726
json-path-api:2.9.0-58.v62e3e85b_a_655
junit:1265.v65b_14fa_f12f0
ldap:725.v3cb_b_711b_1a_ef
logstash:2.5.0218.v0a_ff8fefc12b_
mailer:472.vf7c289a_4b_420
matrix-auth:3.2.2
matrix-project:822.824.v14451b_c0fd42
maven-plugin:3.23
mina-sshd-api-common:2.12.1-101.v85b_e08b_780dd
mina-sshd-api-core:2.12.1-101.v85b_e08b_780dd
momentjs:1.1.1
multiple-scms:0.8
naginator:1.449.ve19751d70eb_0
nodelabelparameter:1.12.0
oauth-credentials:0.646.v02b_66dc03d2e
okhttp-api:4.11.0-172.vda_da_1feeb_c6e
pam-auth:1.10
parameterized-scheduler:262.v00f3d90585cc
parameterized-trigger:806.vf6fff3e28c3e
periodicbackup:2.0
pipeline-build-step:540.vb_e8849e1a_b_d8
pipeline-github:2.8-159.09e4403bc62f
pipeline-github-lib:42.v0739460cda_c4
pipeline-graph-analysis:216.vfd8b_ece330ca_
pipeline-groovy-lib:704.vc58b_8890a_384
pipeline-input-step:495.ve9c153f6067b_
pipeline-milestone-step:119.vdfdc43fc3b_9a_
pipeline-model-api:2.2198.v41dd8ef6dd56
pipeline-model-definition:2.2198.v41dd8ef6dd56
pipeline-model-extensions:2.2198.v41dd8ef6dd56
pipeline-rest-api:2.34
pipeline-stage-step:312.v8cd10304c27a_
pipeline-stage-tags-metadata:2.2198.v41dd8ef6dd56
pipeline-stage-view:2.34
plain-credentials:179.vc5cb_98f6db_38
plugin-util-api:4.1.0
popper2-api:2.11.6-4
preSCMbuildstep:71.v1f2990a_37e27
pubsub-light:1.18
python:1.3
rebuild:332.va_1ee476d8f6d
repo:1.16.0
resource-disposer:0.23
run-condition:1.7
scm-api:690.vfc8b_54395023
script-security:1336.vf33a_a_9863911
snakeyaml-api:2.2-111.vc6598e30cc65
sonar:2.17.2
sonar-gerrit:385.v890738eeff15
sse-gateway:1.26
ssh-credentials:337.v395d2403ccd4
ssh-slaves:2.948.vb_8050d697fec
sshd:3.322.v159e91f6a_550
structs:337.v1b_04ea_4df7c8
timestamper:1.27
token-macro:400.v35420b_922dcb_
trilead-api:2.142.v748523a_76693
uno-choice:2.8.3
variant:60.v7290fc0eb_b_cd
workflow-aggregator:596.v8c21c963d92d
workflow-api:1291.v51fd2a_625da_7
workflow-basic-steps:1058.vcb_fc1e3a_21a_9
workflow-cps:3894.3896.vca_2c931e7935
workflow-cps-global-lib:612.v55f2f80781ef
workflow-durable-task-step:1336.v768003e07199
workflow-job:1400.v7fd111b_ec82f
workflow-multibranch:773.vc4fe1378f1d5
workflow-scm-step:427.v4ca_6512e7df1
workflow-step-api:657.v03b_e8115821b_
workflow-support:907.v6713a_ed8a_573
ws-cleanup:0.45

Reproduction steps

Configure cloud -> GCP configured
Defined a label for provisioning the one-shot VM
In a pipeline job use the label in agent directive

Expected Results

The job gets a VM provisioned in GCP with the node label provisioned

Actual Results

Getting the VM, delay is varying between 2 minutes to 1 hour 30 minutes.
Do not see any logs in Jenkins job console, jenkins log or GCP logs.
In the console log, before provisioning the VM, it prints all the available labels and waits there until the VM is provisioned

Anything else?

No response

Are you interested in contributing a fix?

No response

[rkarasulli]

We see this frequently in our Jenkins log

May 27, 2024 12:36:21 PM WARNING com.google.cloud.graphite.platforms.plugin.client.ComputeClient lambda$waitForOperationCompletion$11
Error retrieving operation.
com.google.api.client.googleapis.json.GoogleJsonResponseException: 404 Not Found
GET https://compute.googleapis.com/compute/v1/projects/my-proj/zones/us-central1-a/operations/operation-1716316733190-618fb21342fd8-e697bbc4-1db85ce9
{
"code" : 404,
"errors" : [ {
"domain" : "global",
"message" : "The resource 'projects/my-proj/zones/us-central1-a/operations/operation-1716316733190-618fb21342fd8-e697bbc4-1db85ce9' was not found",
"reason" : "notFound"
} ],
"message" : "The resource 'projects/my-proj/zones/us-central1-a/operations/operation-1716316733190-618fb21342fd8-e697bbc4-1db85ce9' was not found"
}
at com.google.api.client.googleapis.json.GoogleJsonResponseException.from(GoogleJsonResponseException.java:146)
at com.google.api.client.googleapis.services.json.AbstractGoogleJsonClientRequest.newExceptionOnError(AbstractGoogleJsonClientRequest.java:118)
at com.google.api.client.googleapis.services.json.AbstractGoogleJsonClientRequest.newExceptionOnError(AbstractGoogleJsonClientRequest.java:37)
at com.google.api.client.googleapis.services.AbstractGoogleClientRequest$1.interceptResponse(AbstractGoogleClientRequest.java:439)
at com.google.api.client.http.HttpRequest.execute(HttpRequest.java:1111)
at com.google.api.client.googleapis.services.AbstractGoogleClientRequest.executeUnparsed(AbstractGoogleClientRequest.java:525)
at com.google.api.client.googleapis.services.AbstractGoogleClientRequest.executeUnparsed(AbstractGoogleClientRequest.java:466)
at com.google.api.client.googleapis.services.AbstractGoogleClientRequest.execute(AbstractGoogleClientRequest.java:576)
at com.google.cloud.graphite.platforms.plugin.client.ComputeWrapper.getZoneOperation(ComputeWrapper.java:164)
at com.google.cloud.graphite.platforms.plugin.client.ComputeClient.getZoneOperation(ComputeClient.java:584)
at com.google.cloud.graphite.platforms.plugin.client.ComputeClient.lambda$waitForOperationCompletion$11(ComputeClient.java:673)
at org.awaitility.core.CallableCondition$ConditionEvaluationWrapper.eval(CallableCondition.java:99)
at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:248)
at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:235)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:840)

This may or may not be relevant but could be helpful,
This particular operation is referred first after a 'ZONE_RESOURCE_POOL_EXHAUSTED' error occured in GCP.
Even after the resource is available in GCP, Jenkins is referrrring this occurance.

[nadirollo]

We do see the exact same stack trace. When there's a failure at the GCP endpoint, and the operation is unsuccessful, Jenkins is unable to forget about the operation that failed and our logs are filled with the same above message.
The message indicates the operation has been deleted from GCP (it defaults to 30 days to be deleted from the API)... This means the issue probably occurred 30 days prior to see the message in the jenkins logs...

After we start seeing these errors, we observe Jenkins to lag on creating new instances on demand when a pipeline requests them (although creating them through the UI is immediate).

We haven't been able to find the root cause, but are suffering from this same scenario...

[rkarasulli]

We saw that from some of the earlier events, the nodes were created/tried to be created. In the Jenkins nodes list they were persisting. After cleaning up all the stale nodes, we are not seeing this issue.
We are observing for a week now, we did not see any reoccurrence of it. We are suspecting it was due to the stale nodes that were not deleted.

[bgp-sz]

The error message looks a bit similar this problem #469 - does your problem also go away after a couple of hours or does it persist indefinitely?

[sylvestre]

Removing old nodes in /var/lib/jenkins/nodes/ and restarting jenkins fixed the issue for me