When deploying bosh on Vsphere, Prompt Cleaning up rendered CPI jobs... Finished #2463

yangdeyue-root · 2023-08-15T11:27:51Z

[root@localhost bosh-1]# bosh create-env bosh-deployment/bosh.yml \

--state=state.json \
--vars-store=creds.yml \
-o bosh-deployment/vsphere/cpi.yml \
-o bosh-deployment/vsphere/resource-pool.yml \
-v director_name=SQInternet \
-v internal_cidr=10.2.160.0/24 \
-v internal_gw=10.2.160.254 \
-v internal_ip=10.2.160.1 \
-v network_name="VM-Network-2" \
-v vcenter_dc=Datacenter \
-v vcenter_ds=Datastore_nfs \
-v vcenter_ip=10.2.161.10 \
-v vcenter_user=administrator@sqpass.local \
-v vcenter_password=sdsasus:6A4 \
-v vcenter_templates=SQInternet-templates \
-v vcenter_vms=SQInternet-vms \
-v vcenter_disks=SQInternet-disks \
-v vcenter_rp=ResourcePool \
-v vcenter_cluster=cluster

Deployment manifest: '/home/bosh-1/bosh-deployment/bosh.yml'
Deployment state: 'state.json'

Started validating
Downloading release 'bosh'... Finished (00:00:14)
Validating release 'bosh'... Finished (00:00:02)
Downloading release 'bpm'... Finished (00:00:14)
Validating release 'bpm'... Finished (00:00:01)
Downloading release 'bosh-vsphere-cpi'... Finished (00:00:38)
Validating release 'bosh-vsphere-cpi'... Finished (00:00:06)
Validating cpi release... Finished (00:00:00)
Validating deployment manifest... Finished (00:00:00)
Downloading stemcell... Finished (00:01:28)
Validating stemcell... Finished (00:00:17)
Finished validating (00:03:18)

Started installing CPI
Compiling package 'golang-1-darwin/a1cfad36b0071ef5a83ed91578b48ee30534f7054371bef8b54f3b5fa3034a88'... Finished (00:00:35)
Compiling package 'golang-1-linux/b09468ac73cd3350333a35eb09c980c6a06c5465be0e1ba430da62757dc10a04'... Finished (00:00:33)
Compiling package 'ruby-3.1/8b225e7cc2608305a7b784b5828b2b4b7c7adc3eb14af46e313d64a9e14a3ad6'... Finished (00:05:31)
Compiling package 'iso9660wrap/57da6c48c387379cc701856daa68f9f5269c2441d0195a0c5a735c93d6d2c489'... Finished (00:00:34)
Compiling package 'vsphere_cpi/0ed39dc9e020772257f07af9402ba9a4f8a62c7bd39f7e29e6ba99379398700e'... Finished (00:00:35)
Installing packages... Finished (00:00:12)
Rendering job templates... Finished (00:00:02)
Installing job 'vsphere_cpi'... Finished (00:00:00)
Finished installing CPI (00:08:05)

Uploading stemcell 'bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.181'... Finished (00:04:12)

Started deploying
Creating VM for instance 'bosh/0' from stemcell 'sc-35792cdf-4377-440c-87e8-5af9aaa4b446'... Finished (00:00:25)
Waiting for the agent on VM 'vm-b46cf168-3d38-4683-a977-afe3ddc48111' to be ready... Finished (00:01:43)
Creating disk... Finished (00:00:10)
Attaching disk 'disk-a2189e85-869c-43ba-a151-c1e64ee6ba98' to VM 'vm-b46cf168-3d38-4683-a977-afe3ddc48111'... Finished (00:00:35)
Rendering job templates... Finished (00:00:14)
Compiling package 'golang-1-linux/29f2024e7d815be0694944c3c3c9512914a36a31d5fa1b2cbd2452c8d331ce90'... Skipped [Package already compiled] (00:00:01)
Compiling package 'director-ruby-3.2/84ee2f9d0485530a75822fa03e7fd0c73544aa4c2f6fe24aaebebe1757195efe'... Skipped [Package already compiled] (00:00:00)
Compiling package 'ruby-3.1/8b225e7cc2608305a7b784b5828b2b4b7c7adc3eb14af46e313d64a9e14a3ad6'... Finished (00:05:48)
Compiling package 'tini/3d7b02f3eeb480b9581bec4a0096dab9ebdfa4bc'... Skipped [Package already compiled] (00:00:00)
Compiling package 'bpm-runc/9f66395d85ace4b4d4908069742f7db27dc28d0a'... Skipped [Package already compiled] (00:00:00)
Compiling package 'mysql/67dc3882464cb721ac6f0c093a0b2aeb4d4f963a0c7cd6a8a6e5764f3e193293'... Skipped [Package already compiled] (00:00:00)
Compiling package 'libpq/b309a72768019e24e2c592f3f25ded2679e98cbb90f774c3a4d6b7745760079f'... Skipped [Package already compiled] (00:00:00)
Compiling package 'golang-1-darwin/a1cfad36b0071ef5a83ed91578b48ee30534f7054371bef8b54f3b5fa3034a88'... Finished (00:00:20)
Compiling package 'golang-1-linux/b09468ac73cd3350333a35eb09c980c6a06c5465be0e1ba430da62757dc10a04'... Finished (00:00:20)
Compiling package 'health_monitor/cd4d357a133796e0b6e330719d51b2368da8bf31e57d16d4e02287bf4ecef590'... Skipped [Package already compiled] (00:00:00)
Compiling package 'azure-storage-cli/069862c6e712ee894b1af3ef72a6cac5a03a83810df0cf7528786c12000f5008'... Skipped [Package already compiled] (00:00:00)
Compiling package 'davcli/c08e75b6a7335f5aee645b75cc35006674e7a0db2cd168229c5792f02d6d5d76'... Skipped [Package already compiled] (00:00:00)
Compiling package 's3cli/93ae9d812dcae6f1f924c60279365c53ddbda24b7e4bd8785b1fb9d5f9a57954'... Skipped [Package already compiled] (00:00:00)
Compiling package 'postgres-15/d60a5c68874e269beb9e2b03ea692912229bde7b0076d01f30203be6918323d2'... Skipped [Package already compiled] (00:00:00)
Compiling package 'vsphere_cpi/0ed39dc9e020772257f07af9402ba9a4f8a62c7bd39f7e29e6ba99379398700e'... Finished (00:00:29)
Compiling package 'nginx/ea3eadaa82bb9344018a8798a825b98315b1195bb1d495257f38421b0b7618a5'... Skipped [Package already compiled] (00:00:00)
Compiling package 'nats/91e42e9a8eb4420f55775f33ddcf58293481dccf1ebfe2a640992e063b02f5f1'... Skipped [Package already compiled] (00:00:00)
Compiling package 'verify_multidigest/e2cede15895902b58242b44023502380f68521af9ce68f1ed495158a97714327'... Skipped [Package already compiled] (00:00:00)
Compiling package 'bpm/a677a3b57b36b898c10f9709c9f9813da6d878f0'... Skipped [Package already compiled] (00:00:00)
Compiling package 'postgres-10/e3f2ed31116e1a0c929ae6fcdde983a9d6c000c25cafde8a784fd126e06400f9'... Skipped [Package already compiled] (00:00:00)
Compiling package 'bosh-gcscli/fc2b4b43a11fa3a6e4ac9f86ad4b750975f516371214ff04e01330f26e2a1222'... Skipped [Package already compiled] (00:00:00)
Compiling package 'postgres-13/fe1546f1a699070e23310d860d6c6ea6e61d086eb5cac3e50092cbb4368e8fa1'... Skipped [Package already compiled] (00:00:00)
Compiling package 'director/9da9955131180e1ee189d72ff5b98881706b2012bee63f78473bc513a943fec8'... Skipped [Package already compiled] (00:00:00)
Compiling package 'iso9660wrap/57da6c48c387379cc701856daa68f9f5269c2441d0195a0c5a735c93d6d2c489'... Finished (00:00:12)
Updating instance 'bosh/0'... Finished (00:00:16)
Waiting for instance 'bosh/0' to be running... Failed (00:05:03)
Failed deploying (00:15:46)

Cleaning up rendered CPI jobs... Finished (00:00:00)

Deploying:
Received non-running job state: 'failing'

Exit code 1

Now I don't know how to deal with this problem, hope to get your help

The text was updated successfully, but these errors were encountered:

yangdeyue-root · 2023-08-15T11:42:13Z

However, I can see from vsphere that the virtual machine is started and can be pinged

jpalermo · 2023-08-17T15:50:30Z

Hi @yangdeyue-root, it seems like one of the jobs is failing to start.

If you connect to the VM you can check monit summary to see which job is failing, and look in /var/vcap/sys/logs to find the logs for the failing job to see what went wrong.

If you don't have an easy way to get onto the VM, you can use the bosh cli to ssh to the VM: https://bosh.io/docs/cli-v2/#ssh

Ssh is a bit tricky with a create-env VM, and you'll need to construct the BOSH_AGENT_ENDPOINT and BOSH_AGENT_CERTIFICATE environment variables for it to work.

BOSH_AGENT_ENDPOINT will be https://mbus:MBUS_BOOTSTRAP_PASSWORD@VM_IP_ADDRESS:6868 where the mbus_bootstrap_password can be found in the creds.yml vars store.

BOSH_AGENT_CERTIFICATE can be set to the mbus_bootstrap_ssl/ca value found in the creds.yml vars store.

Once you have those set, you can just run bosh ssh --director and get onto the VM

yangdeyue-root · 2023-08-18T08:03:27Z

@jpalermo Hello, thank you very much for your reply. May I ask whether you are talking about ESXI log or vsphere log? I can check it here

jpalermo · 2023-08-18T23:01:42Z

The logs I'm talking about are on the VM that failed to start properly. You'll need to get onto the VM to check the logs most likely.

If you're unable to get onto the VM using the instructions above, you can also detach the disk from the VM and attach it to another VM you have working to read the logs from there.

yangdeyue-root · 2023-08-22T09:10:51Z

Hello, we have not found the problem. We want to use VirtualBox to install bosh and then deploy cloudfoundry on vsphere. Is this solution ok @jpalermo

jpalermo · 2023-08-23T16:11:52Z

Very out of the ordinary, and you lose a lot of the HA aspects bosh gives you unless you are leaving the VirtualBox running all the time.

But it is possible to deploy a bosh director VM using one CPI (in your case the VirtualBox CPI), but have that director deployed along with a different CPI (the vSphere CPI) that it will use to create VMs itself.

rkoster · 2023-08-24T14:53:24Z

As @jpalermo mentioned above you could detach the disk an look at the logs from an other VM, instructions for this can be found here: https://bosh.io/docs/tips/#unresponsive-vm-logs (from step 3 onwards).

yangdeyue-root · 2023-08-25T09:50:50Z

Thank you very much for your patient answer. Since we have just come into contact with this project and don't know much about it, I still can't connect to the vm and find out the cause of this problem. Could you please ask for more detailed operation steps

jpalermo · 2023-08-25T16:02:02Z

The steps for connecting to the failed VM are here

Also, @rkoster mentioned the alternative, detaching the disk from the failed VM, and attaching it to a working VM to view the logs here: https://bosh.io/docs/tips/#unresponsive-vm-logs

We'd be happy to help with either set of steps, but we're not sure which part you are having trouble with.

yangdeyue-root · 2023-08-28T04:49:36Z

Hi, I think I found the log by separating the faulty vm disk, but I can't pinpoint the exact cause of the failure.
But I see it in sys\log\nats\nats.log [ERR] 10.2.160.1:48052-cid: 7-TLS handshake error: remote error: tls: bad certificate
I am not sure whether this problem caused the failure to start, I will attach the corresponding files, do you have time to help check
log.zip

jpalermo · 2023-09-01T22:13:56Z

Looks like the health_monitor job failed to start up initially, but then did actually start eventually. The logs show this for 8 hours:

E, [2023-08-25T16:33:23.798840 #7] ERROR : NATS client error: SSL_connect returned=1 errno=0 peeraddr=10.2.160.1:4222 state=error: certificate verify failed (certificate is not yet valid)
E, [2023-08-25T16:33:27.818755 #7] ERROR : NATS client error: SSL_connect returned=1 errno=0 peeraddr=10.2.160.1:4222 state=error: certificate verify failed (certificate is not yet valid)
E, [2023-08-25T16:33:31.837752 #7] ERROR : NATS client error: SSL_connect returned=1 errno=0 peeraddr=10.2.160.1:4222 state=error: certificate verify failed (certificate is not yet valid)
I, [2023-08-25T16:33:34.236504 #7]  INFO : HealthMonitor exiting!
I, [2023-08-25T16:33:44.938688 #7]  INFO : HealthMonitor starting...
E, [2023-08-25T16:33:44.957643 #7] ERROR : NATS client error: SSL_connect returned=1 errno=0 peeraddr=10.2.160.1:4222 state=error: certificate verify failed (certificate is not yet valid)
E, [2023-08-25T16:33:48.976823 #7] ERROR : NATS client error: SSL_connect returned=1 errno=0 peeraddr=10.2.160.1:4222 state=error: certificate verify failed (certificate is not yet valid)
E, [2023-08-25T16:33:53.005954 #7] ERROR : NATS client error: SSL_connect returned=1 errno=0 peeraddr=10.2.160.1:4222 state=error: certificate verify failed (certificate is not yet valid)

So it seems like the timestamps on the generated certificates were off by 8 hours. I've never seen this problem before, but maybe make sure the ESX host has the correct time as well as wherever you are running the bosh create-env from.

yangdeyue-root · 2023-09-06T02:26:15Z

It seems that the problem is caused by different time zones. I adjusted the time zones of esxi, vsphere, and centos to UTC, and no error was reported when bosh was installed
However, in the next step, bosh seems to need to download some files from the Internet, but because I am in China, some resources may not be accessible, I want to download some resources in advance, and then reconfigure the download address, but I do not know how to modify the download link

The following is the error message:
[root@localhost bosh-1]# bbl up
step: terraform init
step: terraform apply
step: creating jumpbox
Deployment manifest: '/home/bosh-1/jumpbox-deployment/jumpbox.yml'
Deployment state: '/home/bosh-1/vars/jumpbox-state.json'

Started validating
Downloading release 'os-conf'... Skipped [Found in local cache] (00:00:00)
Validating release 'os-conf'... Finished (00:00:00)
Downloading release 'bosh-vsphere-cpi'... Skipped [Found in local cache] (00:00:00)
Validating release 'bosh-vsphere-cpi'... Finished (00:00:04)
Validating cpi release... Finished (00:00:00)
Validating deployment manifest... Finished (00:00:00)
Downloading stemcell... Skipped [Found in local cache] (00:00:00)
Validating stemcell... Finished (00:00:04)
Finished validating (00:00:09)
No deployment, stemcell or release changes. Skipping deploy.

Succeeded
step: created jumpbox
step: creating bosh director
Deployment manifest: '/home/bosh-1/bosh-deployment/bosh.yml'
Deployment state: '/home/bosh-1/vars/bosh-state.json'

Started validating
Downloading release 'bosh'... Skipped [Found in local cache] (00:00:00)
Validating release 'bosh'... Finished (00:00:01)
Downloading release 'bpm'... Skipped [Found in local cache] (00:00:00)
Validating release 'bpm'... Finished (00:00:00)
Downloading release 'bosh-vsphere-cpi'... Skipped [Found in local cache] (00:00:00)
Validating release 'bosh-vsphere-cpi'... Finished (00:00:04)
Downloading release 'os-conf'... Failed (00:00:31)
Failed validating (00:00:38)

Failed to download the from 'https://bosh.io/d/github.com/cloudfoundry/os-conf-release?v=22.2.0' :
Unable to download:
Performing GET request:
Get "https://bosh.io/d/github.com/cloudfoundry/os-conf-release?v=22.2.0" : SSH: rejected: connect failed (Temporary failure in name resolution)

Exit code 1

I see this link in the file jumpbox-user.yml

name: os-conf
sha1: 5df557f14f073d7ab6a685680a232c1b74c393c5
Url: https://bosh.io/d/github.com/cloudfoundry/os-conf-release?v=22.2.0
version: 22.2.0

I tried to change the link address, but failed

jpalermo · 2023-09-06T04:50:18Z

If you download the file locally, you should be able to change the url attribute to file:// followed by the local path to the file.

yangdeyue-root · 2023-09-08T08:50:16Z

Hi, I have solved the above problems. I am currently trying to install and deploy cloudfoundry. According to the deployment of these tutorials, https://github.com/cloudfoundry/cf-deployment/blob/main/texts/deployment-guide.md, perform the BBL up, throws an error

[root@localhost bosh-1]#
[root@localhost bosh-1]# bbl up
step: terraform init
step: terraform apply
step: creating jumpbox
Deployment manifest: '/home/bosh-1/jumpbox-deployment/jumpbox.yml'
Deployment state: '/home/bosh-1/vars/jumpbox-state.json'

Started validating
Downloading release 'os-conf'... Skipped [Found in local cache] (00:00:00)
Validating release 'os-conf'... Finished (00:00:00)
Downloading release 'bosh-vsphere-cpi'... Skipped [Found in local cache] (00:00:00)
Validating release 'bosh-vsphere-cpi'... Finished (00:00:11)
Validating cpi release... Finished (00:00:00)
Validating deployment manifest... Finished (00:00:00)
Downloading stemcell... Skipped [Found in local cache] (00:00:00)
Validating stemcell... Finished (00:00:09)
Finished validating (00:00:20)
No deployment, stemcell or release changes. Skipping deploy.

Succeeded
step: created jumpbox
step: creating bosh director
Deployment manifest: '/home/bosh-1/bosh-deployment/bosh.yml'
Deployment state: '/home/bosh-1/vars/bosh-state.json'

Started validating
Validating release 'bosh'... Finished (00:00:01)
Validating release 'bpm'... Finished (00:00:00)
Validating release 'bosh-vsphere-cpi'... Finished (00:00:04)
Validating release 'os-conf'... Finished (00:00:00)
Validating release 'uaa'... Finished (00:00:11)
Validating release 'credhub'... Finished (00:00:01)
Validating cpi release... Finished (00:00:00)
Validating deployment manifest... Finished (00:00:00)
Validating stemcell... Finished (00:00:33)
Finished validating (00:00:54)

Started installing CPI
Compiling package 'golang-1-darwin/95867c08201578bc0b7c6df06d5d8778bbe7bf625ae7500ca7f4dd490a84c6dc'... Finished (00:00:19)
Compiling package 'golang-1-linux/2598f3c61c5a9e674fb01f9d5c11ecdbaeb18622b0296ade3fed5e774ee15421'... Finished (00:00:22)
Compiling package 'ruby-3.1/8b225e7cc2608305a7b784b5828b2b4b7c7adc3eb14af46e313d64a9e14a3ad6'... Finished (00:05:49)
Compiling package 'iso9660wrap/b351c796826a0a3a57e13bad036c12a3958c38f9370bbb50540e782582baaf79'... Finished (00:00:30)
Compiling package 'vsphere_cpi/0a06c79f60d3b07b72a9cca3f616ad4248b1f86ffb805f6bd72e671c4a8bafd0'... Finished (00:00:39)
Installing packages... Finished (00:00:12)
Rendering job templates... Finished (00:00:00)
Installing job 'vsphere_cpi'... Finished (00:00:00)
Finished installing CPI (00:07:54)

Uploading stemcell 'bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222'... Finished (00:04:00)

Started deploying
Creating VM for instance 'bosh/0' from stemcell 'sc-d0cfb27d-2881-4d3c-8f1a-9d9bd3be137d'... Finished (00:00:25)
Waiting for the agent on VM 'vm-11602422-f626-4880-9b08-4b82957ec19b' to be ready... Finished (00:01:52)
Creating disk... Finished (00:00:10)
Attaching disk 'disk-5c74b9c3-5bf5-481c-8f10-3d349199b2cf' to VM 'vm-11602422-f626-4880-9b08-4b82957ec19b'... Finished (00:00:39)
Rendering job templates... Finished (00:00:27)
Compiling package 'golang-1-linux/2598f3c61c5a9e674fb01f9d5c11ecdbaeb18622b0296ade3fed5e774ee15421'... Skipped [Package already compiled] (00:00:01)
Compiling package 'director-ruby-3.2/84ee2f9d0485530a75822fa03e7fd0c73544aa4c2f6fe24aaebebe1757195efe'... Skipped [Package already compiled] (00:00:00)
Compiling package 'tini/3d7b02f3eeb480b9581bec4a0096dab9ebdfa4bc'... Skipped [Package already compiled] (00:00:00)
Compiling package 'bpm-runc/9f66395d85ace4b4d4908069742f7db27dc28d0a'... Skipped [Package already compiled] (00:00:00)
Compiling package 'ruby-3.1/8b225e7cc2608305a7b784b5828b2b4b7c7adc3eb14af46e313d64a9e14a3ad6'... Finished (00:06:16)
Compiling package 'mysql/67dc3882464cb721ac6f0c093a0b2aeb4d4f963a0c7cd6a8a6e5764f3e193293'... Skipped [Package already compiled] (00:00:00)
Compiling package 'libpq/b309a72768019e24e2c592f3f25ded2679e98cbb90f774c3a4d6b7745760079f'... Skipped [Package already compiled] (00:00:00)
Compiling package 'openjdk_1.8.0/173e6f8b01cd4416dd49fa774b3920aa4d3c0baef39d2fdbbdb06b1dcaaab3ae'... Skipped [Package already compiled] (00:00:00)
Compiling package 'golang-1-darwin/95867c08201578bc0b7c6df06d5d8778bbe7bf625ae7500ca7f4dd490a84c6dc'... Finished (00:00:17)
Compiling package 'golang-1-linux/2598f3c61c5a9e674fb01f9d5c11ecdbaeb18622b0296ade3fed5e774ee15421'... Finished (00:00:17)
Compiling package 'bosh-gcscli/bb27657944bb3e4ff5750a7cc5945f83804ba4048a95aede6a11dca091ca62bf'... Skipped [Package already compiled] (00:00:00)
Compiling package 'health_monitor/c6f39f527818025d207e3fb005f661acdc61af619c1590a0a171fb462311ea0f'... Skipped [Package already compiled] (00:00:00)
Compiling package 'davcli/dec8dd38ad5ac08a36c324e6e4fd2e35c8b5dae6a3060511c0abd2a03acbdb85'... Skipped [Package already compiled] (00:00:00)
Compiling package 'nats/924f16015eba09509dc09a62641520d2bdf4b8f879d794504bbd1ed88d424f36'... Skipped [Package already compiled] (00:00:00)
Compiling package 'bpm/014f6536612d2d2d5f4473488f67b36403b19142'... Skipped [Package already compiled] (00:00:00)
Compiling package 'vsphere_cpi/0a06c79f60d3b07b72a9cca3f616ad4248b1f86ffb805f6bd72e671c4a8bafd0'... Finished (00:00:30)
Compiling package 'verify_multidigest/878e17f9d0c679d7ea48c6cf82f780f917cb3682f4b3d596e340bcfed79152af'... Skipped [Package already compiled] (00:00:00)
Compiling package 'uaa/7593d5fc0744c44bcfc956f27746a455e07b9a27c6b64693575a64aa58f4375e'... Skipped [Package already compiled] (00:00:05)
Compiling package 'director/f9371999960e9402600f8eea127887fe996a8a5474a0425485e272fadb322051'... Skipped [Package already compiled] (00:00:00)
Compiling package 'azure-storage-cli/3cca33d7e776fb966f13f12db11fac113d5a76ed5f9f2237232aed27b4125365'... Skipped [Package already compiled] (00:00:00)
Compiling package 'postgres-13/fe1546f1a699070e23310d860d6c6ea6e61d086eb5cac3e50092cbb4368e8fa1'... Skipped [Package already compiled] (00:00:00)
Compiling package 'nginx/595e99c97337aa8076b4c2d7924a189387a533b65e64c4a8384776b98bd7a494'... Skipped [Package already compiled] (00:00:00)
Compiling package 's3cli/0625bd15940240a0207e999fb03f0da1116d46814e0d53f5d888c3ff2dbb9021'... Skipped [Package already compiled] (00:00:00)
Compiling package 'credhub/0eedd6d8a99c7cae1300fa9c0f2aa851502dc7025b0296febc5ea2390bb62771'... Skipped [Package already compiled] (00:00:00)
Compiling package 'postgres-15/d60a5c68874e269beb9e2b03ea692912229bde7b0076d01f30203be6918323d2'... Skipped [Package already compiled] (00:00:00)
Compiling package 'luna-hsm-client-7.4/5956cbd4d17c28c2e4c29f3906e3faddc1d7b921708740f1a532a37d5b6fbe29'... Skipped [Package already compiled] (00:00:00)
Compiling package 'postgres-10/e3f2ed31116e1a0c929ae6fcdde983a9d6c000c25cafde8a784fd126e06400f9'... Skipped [Package already compiled] (00:00:00)
Compiling package 'iso9660wrap/b351c796826a0a3a57e13bad036c12a3958c38f9370bbb50540e782582baaf79'... Finished (00:00:13)
Updating instance 'bosh/0'... Finished (00:01:56)
Waiting for instance 'bosh/0' to be running... Finished (00:01:44)
Running the post-start scripts 'bosh/0'... Finished (00:00:01)
Finished deploying (00:15:07)

Cleaning up rendered CPI jobs... Finished (00:00:00)

Succeeded
step: created bosh director
step: generating cloud config
step: applying cloud config
step: applying runtime config
Creating and uploading releases:

Uploading release 'bosh-dns/1.33.0':
Uploading remote release 'https://bosh.io/d/github.com/cloudfoundry/bosh-dns-release?v=1.33.0':
Expected task '1' to succeed but state is 'error'
Exit code 1

Update runtime config: failed to update runtime-config: exit status 1

But it doesn't seem to affect subsequent operations, and I can perform subsequent operations until I make a mistake when I need to upload the stem cells. According to the prompt, it seems to be due to a problem with the cpi

[root@localhost bosh-1]# bosh upload-stemcell bosh-stemcell-1.204-vsphere-esxi-ubuntu-bionic-go_agent.tgz
Using environment 'https://10.2.160.6:25555' as client 'admin'

[----------------------------------------------------] 100.00% 107.90 MiB/s 6.4s
Task 5

Task 5 | 06:34:47 | Update stemcell: Extracting stemcell archive (00:00:12)
Task 5 | 06:34:59 | Update stemcell: Verifying stemcell manifest (00:00:00)
Task 5 | 06:35:03 | Update stemcell: Checking if this stemcell already exists (00:00:00)
Task 5 | 06:35:03 | Update stemcell: Uploading stemcell bosh-vsphere-esxi-ubuntu-bionic-go_agent/1.204 to the cloud (00:01:30)
L Error: Unknown CPI error 'Unknown' with message 'execution expired' in 'create_stemcell' CPI method (CPI request ID: 'cpi-596324')
Task 5 | 06:36:33 | Error: Unknown CPI error 'Unknown' with message 'execution expired' in 'create_stemcell' CPI method (CPI request ID: 'cpi-596324')

Task 5 Started Fri Sep 8 06:34:47 UTC 2023
Task 5 Finished Fri Sep 8 06:36:33 UTC 2023
Task 5 Duration 00:01:46
Task 5 error

Uploading stemcell file:
Expected task '5' to succeed but state is 'error'

Exit code 1

jpalermo · 2023-09-14T14:46:57Z

Hi @yangdeyue-root, seems like there might be some sort of problem with the vsphere configuration.

Both tasks 1 and 5 failed. You can get the full logs by doing a bosh task 1 --debug and bosh task 5 --debug which will probably have more details as to why it failed.

The debug logs can be very large, but probably have some details in them.

yangdeyue-root · 2023-09-18T07:58:37Z

Based on the output, you don't see any additional prompts, just the exact cause of the error

[root@bogon bosh-1]# bosh task 21 --debug
Using environment 'https://10.2.160.6:25555' as client 'admin'

Task 21

I, [2023-09-18T06:20:57.625658 #19] [0x1b9c70] INFO -- TaskHelper: Director Version: 274.1.0
I, [2023-09-18T06:20:57.625743 #19] [0x1b9c70] INFO -- TaskHelper: Enqueuing task: 21
I, [2023-09-18T06:21:00.799505 #142435] [] INFO -- DirectorJobRunner: Looking for task with task id 21
D, [2023-09-18T06:21:00.800997 #142435] [] DEBUG -- DirectorJobRunner: (0.000198s) (conn: 4020) SELECT * FROM "tasks" WHERE "id" = 21
I, [2023-09-18T06:21:00.937587 #142435] [] INFO -- DirectorJobRunner: Found task #<Bosh::Director::Models::Task @values={:id=>21, :state=>"processing", :timestamp=>2023-09-18 06:20:57.563484 UTC, :description=>"create stemcell", :result=>nil, :output=>"/var/vcap/store/director/tasks/21", :checkpoint_time=>2023-09-18 06:20:59.470376 UTC, :type=>"update_stemcell", :username=>"admin", :deployment_name=>nil, :started_at=>nil, :event_output=>"", :result_output=>"", :context_id=>""}>
I, [2023-09-18T06:21:00.937764 #142435] [] INFO -- DirectorJobRunner: Running from worker 'worker_3' on director/5c3b5641-63ef-43a2-7842-92241b2e4c94 (127.0.0.1)
I, [2023-09-18T06:21:00.937847 #142435] [] INFO -- DirectorJobRunner: Starting task: 21
I, [2023-09-18T06:21:00.937980 #142435] [task:21] INFO -- DirectorJobRunner: Creating job
D, [2023-09-18T06:21:00.938655 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000167s) (conn: 4020) SELECT * FROM "tasks" WHERE "id" = 21
D, [2023-09-18T06:21:00.939680 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000151s) (conn: 4020) SELECT * FROM "tasks" WHERE "id" = 21
I, [2023-09-18T06:21:00.940440 #142435] [task:21] INFO -- DirectorJobRunner: Performing task: #<Bosh::Director::Models::Task @values={:id=>21, :state=>"processing", :timestamp=>2023-09-18 06:20:57.563484 UTC, :description=>"create stemcell", :result=>nil, :output=>"/var/vcap/store/director/tasks/21", :checkpoint_time=>2023-09-18 06:20:59.470376 UTC, :type=>"update_stemcell", :username=>"admin", :deployment_name=>nil, :started_at=>nil, :event_output=>"", :result_output=>"", :context_id=>""}>
D, [2023-09-18T06:21:00.950505 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000057s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:00.958006 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000265s) (conn: 4020) UPDATE "tasks" SET "state" = 'processing', "timestamp" = '2023-09-18 06:21:00.949743+0000', "description" = 'create stemcell', "result" = NULL, "output" = '/var/vcap/store/director/tasks/21', "checkpoint_time" = '2023-09-18 06:21:00.949996+0000', "type" = 'update_stemcell', "username" = 'admin', "deployment_name" = NULL, "started_at" = '2023-09-18 06:21:00.949898+0000', "event_output" = '', "result_output" = '', "context_id" = '' WHERE ("id" = 21)
D, [2023-09-18T06:21:01.059291 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.101107s) (conn: 4020) COMMIT
I, [2023-09-18T06:21:01.059589 #142435] [task:21] INFO -- DirectorJobRunner: Processing update stemcell
D, [2023-09-18T06:21:01.063279 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.001128s) (conn: 4020) SELECT * FROM "configs" WHERE ("id" IN (SELECT max("id") FROM "configs" WHERE (("type" = 'cpi') AND ("deleted" IS FALSE)) GROUP BY "name"))
I, [2023-09-18T06:21:01.063661 #142435] [task:21] INFO -- DirectorJobRunner: Update stemcell
D, [2023-09-18T06:21:01.064968 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000058s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:01.065852 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000257s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018061,"stage":"Update stemcell","tags":[],"total":5,"task":"Extracting stemcell archive","index":1,"state":"started","progress":0}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:01.133818 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.067819s) (conn: 4020) COMMIT
I, [2023-09-18T06:21:01.133984 #142435] [task:21] INFO -- DirectorJobRunner: Extracting stemcell archive
D, [2023-09-18T06:21:18.461331 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000073s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:18.462235 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000271s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018078,"stage":"Update stemcell","tags":[],"total":5,"task":"Extracting stemcell archive","index":1,"state":"finished","progress":100}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:18.531788 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.069314s) (conn: 4020) COMMIT
D, [2023-09-18T06:21:18.533288 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000139s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:18.534901 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000467s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018078,"stage":"Update stemcell","tags":[],"total":5,"task":"Verifying stemcell manifest","index":2,"state":"started","progress":0}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:18.592894 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.057631s) (conn: 4020) COMMIT
I, [2023-09-18T06:21:18.593267 #142435] [task:21] INFO -- DirectorJobRunner: Verifying stemcell manifest
I, [2023-09-18T06:21:19.308688 #142435] [task:21] INFO -- DirectorJobRunner: Found stemcell image 'bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222', cloud properties are {"name"=>"bosh-vsphere-esxi-ubuntu-jammy-go_agent", "version"=>"1.222", "infrastructure"=>"vsphere", "hypervisor"=>"esxi", "disk"=>5120, "disk_format"=>"ovf", "container_format"=>"bare", "os_type"=>"linux", "os_distro"=>"ubuntu", "architecture"=>"x86_64", "root_device_name"=>"/dev/sda1"}
I, [2023-09-18T06:21:19.385127 #142435] [task:21] INFO -- DirectorJobRunner: Verifying stemcell image
D, [2023-09-18T06:21:19.385882 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000066s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:19.386655 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000264s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018079,"stage":"Update stemcell","tags":[],"total":5,"task":"Verifying stemcell manifest","index":2,"state":"finished","progress":100}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:19.468595 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.081795s) (conn: 4020) COMMIT
D, [2023-09-18T06:21:19.470180 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000320s) (conn: 4020) SELECT * FROM "configs" WHERE ("id" IN (SELECT max("id") FROM "configs" WHERE (("type" = 'cpi') AND ("deleted" IS FALSE)) GROUP BY "name"))
I, [2023-09-18T06:21:19.470403 #142435] [task:21] INFO -- DirectorJobRunner: Acquiring stemcell lock on bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222
D, [2023-09-18T06:21:19.470679 #142435] [task:21] DEBUG -- DirectorJobRunner: Acquiring lock: lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222
D, [2023-09-18T06:21:19.472533 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000521s) (conn: 4020) SELECT count() AS "count" FROM "locks" WHERE ("name" = 'lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222') LIMIT 1
D, [2023-09-18T06:21:19.866711 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000212s) (conn: 4020) SELECT count() AS "count" FROM "locks" WHERE (("name" = 'lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222') AND ("uid" = '83c1a22b-cb36-48a9-9bd6-67ac62db3fed')) LIMIT 1
D, [2023-09-18T06:21:19.867215 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000056s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:19.868486 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000383s) (conn: 4020) INSERT INTO "locks" ("name", "uid", "expired_at", "task_id") VALUES ('lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222', '83c1a22b-cb36-48a9-9bd6-67ac62db3fed', '2023-09-18 06:25:20.470756+0000', '21') RETURNING *
D, [2023-09-18T06:21:19.915452 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.046527s) (conn: 4020) COMMIT
D, [2023-09-18T06:21:19.915599 #142435] [task:21] DEBUG -- DirectorJobRunner: Acquired lock: lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222
D, [2023-09-18T06:21:19.916292 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000191s) (conn: 4020) SELECT * FROM "tasks" WHERE "id" = 21
D, [2023-09-18T06:21:19.995902 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000070s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:19.996920 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000425s) (conn: 4020) INSERT INTO "events" ("parent_id", "timestamp", "user", "action", "object_type", "object_name", "error", "task", "deployment", "instance", "context_json") VALUES (NULL, '2023-09-18 06:21:19.917000+0000', 'admin', 'acquire', 'lock', 'lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222', NULL, '21', NULL, NULL, '{}') RETURNING *
D, [2023-09-18T06:21:20.012326 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.014967s) (conn: 4020) COMMIT
D, [2023-09-18T06:21:20.104907 #142435] [task:21] DEBUG -- DirectorJobRunner: [external-cpi] [cpi-461169] request: {"method":"info","arguments":[],"context":{"director_uuid":"60260d86-7d16-41c6-9570-0e9d0fae51e1","request_id":"cpi-461169"}} with command: /var/vcap/jobs/vsphere_cpi/bin/cpi
D, [2023-09-18T06:21:23.637556 #142435] [task:21] DEBUG -- DirectorJobRunner: [external-cpi] [cpi-461169] response: {"result":{"stemcell_formats":["vsphere-ovf","vsphere-ova"],"api_version":2},"error":null,"log":""}, err: I, [2023-09-18T06:21:23.519629 #142463] INFO -- [req_id cpi-461169]: Starting info...
I, [2023-09-18T06:21:23.520805 #142463] INFO -- : Fetching vSphere version to locate SDK
I, [2023-09-18T06:21:23.624296 #142463] INFO -- [req_id cpi-461169]: Finished info in 0.1 seconds
, exit_status: 0
D, [2023-09-18T06:21:23.638213 #142435] [task:21] DEBUG -- DirectorJobRunner: Using cpi_version 2 for CPI
D, [2023-09-18T06:21:23.638529 #142435] [task:21] DEBUG -- DirectorJobRunner: [external-cpi] [cpi-336675] request: {"method":"info","arguments":[],"context":{"director_uuid":"60260d86-7d16-41c6-9570-0e9d0fae51e1","request_id":"cpi-336675"},"api_version":2} with command: /var/vcap/jobs/vsphere_cpi/bin/cpi
D, [2023-09-18T06:21:25.558163 #142435] [task:21] DEBUG -- DirectorJobRunner: [external-cpi] [cpi-336675] response: {"result":{"stemcell_formats":["vsphere-ovf","vsphere-ova"],"api_version":2},"error":null,"log":""}, err: I, [2023-09-18T06:21:25.439984 #142466] INFO -- [req_id cpi-336675]: Starting info...
I, [2023-09-18T06:21:25.440914 #142466] INFO -- : Fetching vSphere version to locate SDK
I, [2023-09-18T06:21:25.546052 #142466] INFO -- [req_id cpi-336675]: Finished info in 0.11 seconds
, exit_status: 0
D, [2023-09-18T06:21:25.561527 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000064s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:25.562383 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000294s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018085,"stage":"Update stemcell","tags":[],"total":5,"task":"Checking if this stemcell already exists","index":3,"state":"started","progress":0}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:25.564873 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.002322s) (conn: 4020) COMMIT
I, [2023-09-18T06:21:25.565036 #142435] [task:21] INFO -- DirectorJobRunner: Checking if this stemcell already exists
D, [2023-09-18T06:21:25.566584 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000311s) (conn: 4020) SELECT * FROM "configs" WHERE ("id" IN (SELECT max("id") FROM "configs" WHERE (("type" = 'cpi') AND ("deleted" IS FALSE)) GROUP BY "name"))
D, [2023-09-18T06:21:25.568180 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000371s) (conn: 4020) SELECT * FROM "stemcells" WHERE (("name" = 'bosh-vsphere-esxi-ubuntu-jammy-go_agent') AND ("version" = '1.222'))
D, [2023-09-18T06:21:25.569288 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000052s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:25.569941 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000202s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018085,"stage":"Update stemcell","tags":[],"total":5,"task":"Checking if this stemcell already exists","index":3,"state":"finished","progress":100}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:25.571462 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.001377s) (conn: 4020) COMMIT
D, [2023-09-18T06:21:25.572041 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000050s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:25.572753 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000264s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018085,"stage":"Update stemcell","tags":[],"total":5,"task":"Uploading stemcell bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222 to the cloud","index":4,"state":"started","progress":0}
') WHERE ("id" = 21)
D, [2023-09-18T06:21:25.574642 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.001743s) (conn: 4020) COMMIT
I, [2023-09-18T06:21:25.574784 #142435] [task:21] INFO -- DirectorJobRunner: Uploading stemcell bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222 to the cloud
D, [2023-09-18T06:21:25.575055 #142435] [task:21] DEBUG -- DirectorJobRunner: [external-cpi] [cpi-730423] request: {"method":"create_stemcell","arguments":["/var/vcap/data/director/tmp/stemcell20230918-142435-m22yti/image",{"name":"bosh-vsphere-esxi-ubuntu-jammy-go_agent","version":"1.222","infrastructure":"vsphere","hypervisor":"esxi","disk":5120,"disk_format":"ovf","container_format":"bare","os_type":"linux","os_distro":"ubuntu","architecture":"x86_64","root_device_name":"/dev/sda1"}],"context":{"director_uuid":"60260d86-7d16-41c6-9570-0e9d0fae51e1","request_id":"cpi-730423"},"api_version":2} with command: /var/vcap/jobs/vsphere_cpi/bin/cpi
D, [2023-09-18T06:21:30.951751 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000074s) (conn: 4020) BEGIN
D, [2023-09-18T06:21:30.952747 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000296s) (conn: 4020) UPDATE "tasks" SET "checkpoint_time" = '2023-09-18 06:21:30.949835+0000' WHERE ("id" = 21)
D, [2023-09-18T06:21:30.956071 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.003154s) (conn: 4020) COMMIT
D, [2023-09-18T06:22:00.958336 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000150s) (conn: 4020) BEGIN
D, [2023-09-18T06:22:00.960486 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000632s) (conn: 4020) UPDATE "tasks" SET "checkpoint_time" = '2023-09-18 06:22:00.956438+0000' WHERE ("id" = 21)
D, [2023-09-18T06:22:01.020465 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.059644s) (conn: 4020) COMMIT
D, [2023-09-18T06:22:31.022942 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000171s) (conn: 4020) BEGIN
D, [2023-09-18T06:22:31.054441 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000859s) (conn: 4020) UPDATE "tasks" SET "checkpoint_time" = '2023-09-18 06:22:31.020840+0000' WHERE ("id" = 21)
D, [2023-09-18T06:22:31.061289 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.006463s) (conn: 4020) COMMIT
D, [2023-09-18T06:23:01.062647 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000083s) (conn: 4020) BEGIN
D, [2023-09-18T06:23:01.064452 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000653s) (conn: 4020) UPDATE "tasks" SET "checkpoint_time" = '2023-09-18 06:23:01.061725+0000' WHERE ("id" = 21)
D, [2023-09-18T06:23:01.067366 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.002495s) (conn: 4020) COMMIT
D, [2023-09-18T06:23:20.104989 #142435] [] DEBUG -- DirectorJobRunner: Renewing lock: lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222
D, [2023-09-18T06:23:20.111207 #142435] [] DEBUG -- DirectorJobRunner: (0.002622s) (conn: 4020) UPDATE "locks" SET "expired_at" = '2023-09-18 06:27:21.105283+0000' WHERE (("name" = 'lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222') AND ("uid" = '83c1a22b-cb36-48a9-9bd6-67ac62db3fed'))
D, [2023-09-18T06:23:31.069208 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000148s) (conn: 4020) BEGIN
D, [2023-09-18T06:23:31.071042 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.000519s) (conn: 4020) UPDATE "tasks" SET "checkpoint_time" = '2023-09-18 06:23:31.067836+0000' WHERE ("id" = 21)
D, [2023-09-18T06:23:31.073775 #142435] [task:21-checkpoint] DEBUG -- DirectorJobRunner: (0.002295s) (conn: 4020) COMMIT
D, [2023-09-18T06:23:56.645885 #142435] [task:21] DEBUG -- DirectorJobRunner: [external-cpi] [cpi-730423] response: {"result":null,"error":{"type":"Unknown","message":"execution expired","ok_to_retry":false},"log":"Rescued Unknown: execution expired. backtrace: /var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:611:in initialize'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:611:in new'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:611:in create_socket'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/ssl_socket.rb:21:in create_socket'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:752:in block in connect'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/3.1.0/timeout.rb:117:in timeout'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:748:in connect'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:511:in query'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:177:in query'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient.rb:1242:in do_get_block'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient.rb:1019:in block in do_request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient.rb:1133:in protect_keep_alive_disconnected'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient.rb:1014:in do_request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient.rb:856:in request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/httpclient-2.8.3/lib/httpclient.rb:765:in post'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/base_http_client.rb:83:in do_request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/base_http_client.rb:50:in post'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/file_provider.rb:183:in block in do_request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/file_provider.rb:190:in block in do_request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/retryer.rb:9:in block in try'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/retryer.rb:8:in times'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/retryer.rb:8:in try'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/file_provider.rb:189:in do_request'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/file_provider.rb:43:in upload_file_to_url'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:1014:in block (2 levels) in upload_ovf'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:999:in each'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:999:in block in upload_ovf'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:997:in each'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:997:in upload_ovf'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:249:in block (3 levels) in create_stemcell'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:217:in each'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:217:in block (2 levels) in create_stemcell'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/3.1.0/tmpdir.rb:96:in mktmpdir'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:186:in block in create_stemcell'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in with_thread_name'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/lib/cloud/vsphere/cloud.rb:181:in create_stemcell'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/3.1.0/forwardable.rb:238:in create_stemcell'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in public_send'\n/var/vcap/data/packages/vsphere_cpi/b47f58259138ebc3b45cac8dd664deb92f11e5cd/vendor/bundle/ruby/3.1.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in run'\n/var/vcap/packages/vsphere_cpi/bin/vsphere_cpi:72:in <top (required)>'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/cli/exec.rb:58:in load'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/cli/exec.rb:58:in kernel_load'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/cli/exec.rb:23:in run'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/cli.rb:483:in exec'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/vendor/thor/lib/thor/command.rb:27:in run'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in invoke_command'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/vendor/thor/lib/thor.rb:392:in dispatch'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/cli.rb:31:in dispatch'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/vendor/thor/lib/thor/base.rb:485:in start'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/cli.rb:25:in start'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/gems/3.1.0/gems/bundler-2.3.11/exe/bundle:48:in block in <top (required)>'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/site_ruby/3.1.0/bundler/friendly_errors.rb:103:in with_friendly_errors'\n/var/vcap/data/packages/ruby-3.1.2-r0.91.0/38f75434fea25aaa8e74c99f14dcfee394081a03/lib/ruby/gems/3.1.0/gems/bundler-2.3.11/exe/bundle:36:in <top (required)>'\n/var/vcap/packages/ruby-3.1.2-r0.91.0/bin/bundle:25:in load'\n/var/vcap/packages/ruby-3.1.2-r0.91.0/bin/bundle:25:in <main>'"}, err: I, [2023-09-18T06:21:27.379506 #142468] INFO -- [req_id cpi-730423]: Starting create_stemcell... I, [2023-09-18T06:21:27.379834 #142468] INFO -- : Fetching vSphere version to locate SDK I, [2023-09-18T06:21:31.106259 #142468] INFO -- : Loaded vSphere 6.5 SDK D, [2023-09-18T06:21:34.743904 #142468] DEBUG -- [req_id cpi-730423]: Running method 'RetrieveServiceContent'... D, [2023-09-18T06:21:34.890325 #142468] DEBUG -- [req_id cpi-730423]: Running method 'Login'... D, [2023-09-18T06:21:35.410475 #142468] DEBUG -- [req_id cpi-730423]: Running method 'FindExtension'... D, [2023-09-18T06:21:35.412622 #142468] DEBUG -- [req_id cpi-730423]: Running method 'RetrieveServiceContent'... D, [2023-09-18T06:21:35.527158 #142468] DEBUG -- [req_id cpi-730423]: Extension already exists I, [2023-09-18T06:21:35.529184 #142468] INFO -- [req_id cpi-730423]: Extracting stemcell to: /var/vcap/data/director/tmp/d20230918-142468-5e4859 D, [2023-09-18T06:21:35.566177 #142468] DEBUG -- [req_id cpi-730423]: Running method 'Login'... D, [2023-09-18T06:21:35.645525 #142468] DEBUG -- [req_id cpi-730423]: Running method 'Logout'... I, [2023-09-18T06:22:52.018827 #142468] INFO -- [req_id cpi-730423]: Generated name: sc-a14b9eec-14f3-4d44-bac9-2f09b0b628d0 D, [2023-09-18T06:22:52.022996 #142468] DEBUG -- [req_id cpi-730423]: All clusters provided: {"cluster"=>#<VSphereCloud::ClusterConfig:0x00007f3abed82a70 @name="cluster", @config={"resource_pool"=>"Resource-Pool"}>} D, [2023-09-18T06:22:52.023519 #142468] DEBUG -- [req_id cpi-730423]: Running method 'FindByInventoryPath'... I, [2023-09-18T06:22:52.098428 #142468] INFO -- [req_id cpi-730423]: Using global datastore pattern Datastore_nfs and global datastore cluster pattern persistent: false I, [2023-09-18T06:22:52.099049 #142468] INFO -- [req_id cpi-730423]: Initiating VM Allocator with VM Placement Criteria: Disk Config: [Disk ==> Disk CID: Size:1219 Ephemeral:true Target-DS:Datastore_nfs Existing-DS:] Req Memory: 0 Mem Headroom: 128 I, [2023-09-18T06:22:52.099194 #142468] INFO -- [req_id cpi-730423]: Gathering vm placement resources for vm placement allocator pipeline D, [2023-09-18T06:22:53.732870 #142468] DEBUG -- [req_id cpi-730423]: Running method 'FindByInventoryPath'... D, [2023-09-18T06:22:53.744720 #142468] DEBUG -- [req_id cpi-730423]: Fetching Memory utilization for Resource Pool Resource-Pool D, [2023-09-18T06:22:53.766983 #142468] DEBUG -- [req_id cpi-730423]: Fetching Memory utilization for Resource Pool Resource-Pool D, [2023-09-18T06:22:53.781625 #142468] DEBUG -- [req_id cpi-730423]: Filter VM Placement Cluster: cluster Cluster free memory: 753992, host group free memory: 753992 for free memory required: 128 D, [2023-09-18T06:22:53.781753 #142468] DEBUG -- [req_id cpi-730423]: Filter VM Placement Cluster: cluster hosts: datastores: [<Datastore: / datastore_15>, <Datastore: / datastore_13>, <Datastore: / datastore_16>, <Datastore: / datastore_14>, <Datastore: / Datastore_nfs>] for combination of DS satisfying disk configurations D, [2023-09-18T06:22:53.781829 #142468] DEBUG -- [req_id cpi-730423]: Trying to find placement for Disk ==> Disk CID: Size:1219 Ephemeral:true Target-DS:Datastore_nfs Existing-DS: I, [2023-09-18T06:22:53.782060 #142468] INFO -- [req_id cpi-730423]: Initiating Disk Allocator with Storage Criteria: Space Req: 1219 Target Pattern: Datastore_nfs Existing-DS Pattern: D, [2023-09-18T06:22:54.062670 #142468] DEBUG -- [req_id cpi-730423]: Found <Datastore: / Datastore_nfs> for Disk ==> Disk CID: Size:1219 Ephemeral:true Target-DS:Datastore_nfs Existing-DS: D, [2023-09-18T06:22:54.062844 #142468] DEBUG -- [req_id cpi-730423]: All clusters provided: {"cluster"=>#<VSphereCloud::ClusterConfig:0x00007f3abed82a70 @name="cluster", @config={"resource_pool"=>"Resource-Pool"}>} I, [2023-09-18T06:22:55.270166 #142468] INFO -- [req_id cpi-730423]: Deploying to: (VSphereCloud::Resources::Cluster (name="cluster")) / (VSphereCloud::Resources::Datastore (name="Datastore_nfs", mob="<[Vim.Datastore] datastore-29>")) D, [2023-09-18T06:22:55.272113 #142468] DEBUG -- [req_id cpi-730423]: Running method 'CreateImportSpec'... D, [2023-09-18T06:22:55.322396 #142468] DEBUG -- [req_id cpi-730423]: Running method 'FindByInventoryPath'... I, [2023-09-18T06:22:55.327143 #142468] INFO -- [req_id cpi-730423]: Importing VApp D, [2023-09-18T06:22:55.327256 #142468] DEBUG -- [req_id cpi-730423]: Running method 'ImportVApp'... I, [2023-09-18T06:22:55.362421 #142468] INFO -- [req_id cpi-730423]: Waiting for NFC lease to become ready I, [2023-09-18T06:22:56.388713 #142468] INFO -- [req_id cpi-730423]: Uploading I, [2023-09-18T06:22:56.404907 #142468] INFO -- [req_id cpi-730423]: Uploading disk to: https://10.2.162.15/nfc/52c2d270-9af0-9d3e-5785-dec14a015ecd/disk-0.vmdk I, [2023-09-18T06:22:56.405006 #142468] INFO -- [req_id cpi-730423]: Uploading file to https://10.2.162.15/nfc/52c2d270-9af0-9d3e-5785-dec14a015ecd/disk-0.vmdk... I, [2023-09-18T06:23:56.418310 #142468] INFO -- [req_id cpi-730423]: Finished create_stemcell in 149.03 seconds D, [2023-09-18T06:23:56.419627 #142468] DEBUG -- [req_id cpi-730423]: Running method 'Logout'... , exit_status: 0 D, [2023-09-18T06:23:56.672993 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000155s) (conn: 4020) BEGIN D, [2023-09-18T06:23:56.674816 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000557s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018236,"stage":"Update stemcell","tags":[],"total":5,"task":"Uploading stemcell bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222 to the cloud","index":4,"state":"failed","progress":100,"data":{"error":"Unknown CPI error ''Unknown'' with message ''execution expired'' in ''create_stemcell'' CPI method (CPI request ID: ''cpi-730423'')"}} ') WHERE ("id" = 21) D, [2023-09-18T06:23:56.677214 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.002055s) (conn: 4020) COMMIT D, [2023-09-18T06:23:56.682411 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.002113s) (conn: 4020) DELETE FROM "locks" WHERE (("name" = 'lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222') AND ("uid" = '83c1a22b-cb36-48a9-9bd6-67ac62db3fed')) D, [2023-09-18T06:23:56.682696 #142435] [task:21] DEBUG -- DirectorJobRunner: Deleted lock: lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222 uid: 83c1a22b-cb36-48a9-9bd6-67ac62db3fed D, [2023-09-18T06:23:56.684862 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000152s) (conn: 4020) BEGIN D, [2023-09-18T06:23:56.686833 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000515s) (conn: 4020) INSERT INTO "events" ("parent_id", "timestamp", "user", "action", "object_type", "object_name", "error", "task", "deployment", "instance", "context_json") VALUES (NULL, '2023-09-18 06:23:56.683036+0000', 'admin', 'release', 'lock', 'lock:stemcells:bosh-vsphere-esxi-ubuntu-jammy-go_agent:1.222', NULL, '21', NULL, NULL, '{}') RETURNING * D, [2023-09-18T06:23:56.690425 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.002372s) (conn: 4020) COMMIT D, [2023-09-18T06:23:56.855721 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000107s) (conn: 4020) BEGIN D, [2023-09-18T06:23:56.856932 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000560s) (conn: 4020) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1695018236,"error":{"code":100,"message":"Unknown CPI error ''Unknown'' with message ''execution expired'' in ''create_stemcell'' CPI method (CPI request ID: ''cpi-730423'')"}} ') WHERE ("id" = 21) D, [2023-09-18T06:23:56.858491 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.001385s) (conn: 4020) COMMIT E, [2023-09-18T06:23:56.858721 #142435] [task:21] ERROR -- DirectorJobRunner: Unknown CPI error 'Unknown' with message 'execution expired' in 'create_stemcell' CPI method (CPI request ID: 'cpi-730423') /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi.rb:247:in handle_error'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi.rb:159:in invoke_cpi_method' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi.rb:76:in create_stemcell'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi_response_wrapper.rb:35:in public_send' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi_response_wrapper.rb:35:in invoke_cpi_method'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi_response_wrapper.rb:12:in create_stemcell' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/update_stemcell.rb:112:in block (3 levels) in perform'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/base_job.rb:54:in block in track_and_log' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/event_log.rb:105:in advance_and_track'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/base_job.rb:52:in track_and_log' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/update_stemcell.rb:110:in block (2 levels) in perform'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/update_stemcell.rb:80:in each' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/update_stemcell.rb:80:in block in perform'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/lock_helper.rb:29:in block in with_stemcell_lock' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/lock.rb:79:in lock'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/lock_helper.rb:29:in with_stemcell_lock' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/update_stemcell.rb:79:in perform'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/job_runner.rb:99:in perform_job' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/job_runner.rb:34:in block in run'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh_common-0.0.0/lib/common/thread_formatter.rb:50:in with_thread_name' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/job_runner.rb:34:in run'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/base_job.rb:9:in perform' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/db_job.rb:32:in block in perform'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/bosh-director-0.0.0/lib/bosh/director/jobs/db_job.rb:98:in block (3 levels) in run' /var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/eventmachine-1.3.0.dev.1/lib/eventmachine.rb:1078:in block in spawn_threadpool'
/var/vcap/data/packages/director/a4e0cbcd15c51aedcbf08c710fae6a9830c92c13/gem_home/ruby/3.1.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
D, [2023-09-18T06:23:56.860071 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000486s) (conn: 4020) SELECT * FROM "tasks" WHERE "id" = 21
D, [2023-09-18T06:23:56.863749 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000101s) (conn: 4020) BEGIN
D, [2023-09-18T06:23:56.865136 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.000492s) (conn: 4020) UPDATE "tasks" SET "state" = 'error', "timestamp" = '2023-09-18 06:23:56.863155+0000', "description" = 'create stemcell', "result" = 'Unknown CPI error ''Unknown'' with message ''execution expired'' in ''create_stemcell'' CPI method (CPI request ID: ''cpi-730423'')', "output" = '/var/vcap/store/director/tasks/21', "checkpoint_time" = '2023-09-18 06:23:31.067836+0000', "type" = 'update_stemcell', "username" = 'admin', "deployment_name" = NULL, "started_at" = '2023-09-18 06:21:00.949898+0000', "event_output" = '{"time":1695018061,"stage":"Update stemcell","tags":[],"total":5,"task":"Extracting stemcell archive","index":1,"state":"started","progress":0}
{"time":1695018078,"stage":"Update stemcell","tags":[],"total":5,"task":"Extracting stemcell archive","index":1,"state":"finished","progress":100}
{"time":1695018078,"stage":"Update stemcell","tags":[],"total":5,"task":"Verifying stemcell manifest","index":2,"state":"started","progress":0}
{"time":1695018079,"stage":"Update stemcell","tags":[],"total":5,"task":"Verifying stemcell manifest","index":2,"state":"finished","progress":100}
{"time":1695018085,"stage":"Update stemcell","tags":[],"total":5,"task":"Checking if this stemcell already exists","index":3,"state":"started","progress":0}
{"time":1695018085,"stage":"Update stemcell","tags":[],"total":5,"task":"Checking if this stemcell already exists","index":3,"state":"finished","progress":100}
{"time":1695018085,"stage":"Update stemcell","tags":[],"total":5,"task":"Uploading stemcell bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222 to the cloud","index":4,"state":"started","progress":0}
{"time":1695018236,"stage":"Update stemcell","tags":[],"total":5,"task":"Uploading stemcell bosh-vsphere-esxi-ubuntu-jammy-go_agent/1.222 to the cloud","index":4,"state":"failed","progress":100,"data":{"error":"Unknown CPI error ''Unknown'' with message ''execution expired'' in ''create_stemcell'' CPI method (CPI request ID: ''cpi-730423'')"}}
{"time":1695018236,"error":{"code":100,"message":"Unknown CPI error ''Unknown'' with message ''execution expired'' in ''create_stemcell'' CPI method (CPI request ID: ''cpi-730423'')"}}
', "result_output" = '', "context_id" = '' WHERE ("id" = 21)
D, [2023-09-18T06:23:56.866735 #142435] [task:21] DEBUG -- DirectorJobRunner: (0.001417s) (conn: 4020) COMMIT
I, [2023-09-18T06:23:56.867042 #142435] [] INFO -- DirectorJobRunner: Task took 2 minutes 55.92899081300001 seconds to process.

Task 21 error

Capturing task '21' output:
Expected task '21' to succeed but state is 'error'

Exit code 1

jpalermo · 2023-09-21T16:25:36Z

Yeah, it looks like the http client in the vSphere CPI is timing out while trying to upload the stemcell to vSphere.

Does where you're running this from have access to the vCenter and the associated hosts and datastores?

jpalermo · 2023-10-05T14:45:19Z

Hey @yangdeyue-root, have you had a chance to look at this again?

yangdeyue-root · 2023-10-07T01:24:50Z

Hi, I am still investigating this problem, and it has not been solved yet. I saw that ovf deployment task was submitted for execution on vsphere, but the final result was displayed as failure @jpalermo

jpalermo · 2023-10-12T19:34:18Z

Yeah, I'm not sure what the error says but it does seem like there may either be some sort configuration problem in vSphere itself (maybe connectivity between ESX hosts and the datastore?), or something is wrong with the vSphere config given to the CPI (incorrect datastore or something)

yangdeyue-root · 2023-10-13T01:23:26Z

When I deployed bosh, I saw the steps for deploying the template in vsphere. If there is a problem between vsphere and esxi, there should be an error reported in the previous steps for deploying the template, instead of successful execution. What do you think

jpalermo · 2023-10-13T04:02:56Z

Yeah, that is true.

However, when you successfully created the bosh director, the stemcell was uploaded to the datastore from when you ran the bbl up from. But in the new case where you are performing a bosh deploy, it's the bosh director VM that will be uploading the new stemcell.

Could there be a communication problem caused by the fact that the bosh director is trying to upload the stemcell to the datastore from within the ESX host? That's not a problem I've ever seen before, but I could see a situation where connectivity from the VMs running ESX would be blocked from accessing the datstore.

yangdeyue-root · 2023-10-20T04:14:04Z

Speaking of this, I think of a problem, we have successfully deployed cloudfoundry once before, the first deployment, there are two disks on the machine, esxi system is installed in disk 1, the subsequent deployment of cloudfoundry is installed in disk 2, there was no such error at that time, during this deployment, There is only one disk, and the system and cloudfoundry are in the same disk. I don't know if it is caused by this problem. Now I am trying to mount a new disk on the machine and then try to deploy it

yangdeyue-root · 2023-10-23T07:32:29Z

Hi, I solved this problem, because the network problem caused the failure, so I could not upload, but I did not understand another problem. In my network architecture, the address of the device where esxi is installed is 10.2.162.11, and the address of my vsphere is 10.2.160.250. I assigned network segment 10.2.160.0 to bosh. After bosh was deployed, three VMS were generated, respectively 10.2.160.1 10.2.160.5 10.2.160.6. However, there was a very special phenomenon. 10.2.160.1 This VM can communicate with the esxi host and can ping through it, but 10.2.160.5 and 10.2.160.6 cannot communicate with esxi. My architecture diagram will be uploaded. Could you please help me explain this problem

cunnie · 2024-01-16T17:03:10Z

Hi @yangdeyue-root

Is your issue fixed? If not, could you please try the following experiment:

On the VM at 10.2.160.5:

sudo tcpdump -n icmp

On the ESX host (10.2.162.11):

ping 10.2.160.5

And let me know the output. This will help determine if the traffic is being blocked from the ESXi host to the VM or from the VM to the ESXi host.

yangdeyue-root · 2024-01-17T01:46:55Z

I've solved this problem by putting all the virtual machines on the same network segment so that they can be accessed from one VM to another
But I still do not understand the reasons for the above problems

This was referenced Sep 7, 2023

Difficulties with deploying bosh using virtualbox cloudfoundry/bosh-deployment#457

Closed

Create a Jumpbox and a BOSH Director error cloudfoundry/bosh-bootloader#587

Closed

Create a Jumpbox and a BOSH Director error #2468

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

When deploying bosh on Vsphere, Prompt Cleaning up rendered CPI jobs... Finished #2463

When deploying bosh on Vsphere, Prompt Cleaning up rendered CPI jobs... Finished #2463

yangdeyue-root commented Aug 15, 2023

yangdeyue-root commented Aug 15, 2023

jpalermo commented Aug 17, 2023

yangdeyue-root commented Aug 18, 2023

jpalermo commented Aug 18, 2023

yangdeyue-root commented Aug 22, 2023

jpalermo commented Aug 23, 2023

rkoster commented Aug 24, 2023

yangdeyue-root commented Aug 25, 2023

jpalermo commented Aug 25, 2023

yangdeyue-root commented Aug 28, 2023

jpalermo commented Sep 1, 2023

yangdeyue-root commented Sep 6, 2023

jpalermo commented Sep 6, 2023

yangdeyue-root commented Sep 8, 2023

jpalermo commented Sep 14, 2023

yangdeyue-root commented Sep 18, 2023

jpalermo commented Sep 21, 2023

jpalermo commented Oct 5, 2023

yangdeyue-root commented Oct 7, 2023

jpalermo commented Oct 12, 2023

yangdeyue-root commented Oct 13, 2023

jpalermo commented Oct 13, 2023

yangdeyue-root commented Oct 20, 2023

yangdeyue-root commented Oct 23, 2023

cunnie commented Jan 16, 2024

yangdeyue-root commented Jan 17, 2024

When deploying bosh on Vsphere, Prompt Cleaning up rendered CPI jobs... Finished #2463

When deploying bosh on Vsphere, Prompt Cleaning up rendered CPI jobs... Finished #2463

Comments

yangdeyue-root commented Aug 15, 2023

yangdeyue-root commented Aug 15, 2023

jpalermo commented Aug 17, 2023

yangdeyue-root commented Aug 18, 2023

jpalermo commented Aug 18, 2023

yangdeyue-root commented Aug 22, 2023

jpalermo commented Aug 23, 2023

rkoster commented Aug 24, 2023

yangdeyue-root commented Aug 25, 2023

jpalermo commented Aug 25, 2023

yangdeyue-root commented Aug 28, 2023

jpalermo commented Sep 1, 2023

yangdeyue-root commented Sep 6, 2023

jpalermo commented Sep 6, 2023

yangdeyue-root commented Sep 8, 2023

jpalermo commented Sep 14, 2023

yangdeyue-root commented Sep 18, 2023

jpalermo commented Sep 21, 2023

jpalermo commented Oct 5, 2023

yangdeyue-root commented Oct 7, 2023

jpalermo commented Oct 12, 2023

yangdeyue-root commented Oct 13, 2023

jpalermo commented Oct 13, 2023

yangdeyue-root commented Oct 20, 2023

yangdeyue-root commented Oct 23, 2023

cunnie commented Jan 16, 2024

yangdeyue-root commented Jan 17, 2024