search

cloudfoundry / bosh

Cloud Foundry BOSH is an open source tool chain for release engineering, deployment and lifecycle management of large scale distributed services.
https://bosh.io
Apache License 2.0
2.03k stars 657 forks source link

Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method #2399

Closed kwonsoonwoo closed 1 year ago

kwonsoonwoo commented 2 years ago

Describe the bug When trying to deploy a specific deployment with bosh, cpi error occurs (even when recreate and cck)

To Reproduce


Task 303801 | 05:23:03 | Preparing deployment: Preparing deployment (00:00:02)
Task 303801 | 05:23:05 | Preparing deployment: Rendering templates (00:00:02)
Task 303801 | 05:23:07 | Preparing package compilation: Finding packages to compile (00:00:00)
Task 303801 | 05:23:07 | Creating missing vms: web/aa615f9e-76ce-4c1e-8f91-3b75b0a75044 (0)
Task 303801 | 05:23:07 | Creating missing vms: db/a1908862-3676-47e1-8e39-f6ada8501c85 (0)
Task 303801 | 05:23:07 | Creating missing vms: worker/33c3b784-1f2c-4fc1-8d24-bf094f4dae16 (0)
Task 303801 | 05:23:43 | Creating missing vms: web/aa615f9e-76ce-4c1e-8f91-3b75b0a75044 (0) (00:00:36)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-621099')
Task 303801 | 05:23:43 | Creating missing vms: db/a1908862-3676-47e1-8e39-f6ada8501c85 (0) (00:00:36)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-683989')
Task 303801 | 05:23:44 | Creating missing vms: worker/33c3b784-1f2c-4fc1-8d24-bf094f4dae16 (0) (00:00:37)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-598709')
Task 303801 | 05:23:44 | Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-621099')

Task 303801 Started  Fri Sep 16 05:23:03 UTC 2022
Task 303801 Finished Fri Sep 16 05:23:44 UTC 2022
Task 303801 Duration 00:00:41
Task 303801 error

Updating deployment:
  Expected task '303801' to succeed but state is 'error'

Exit code 1

Expected behavior I want the bosh director to run deploy, cck, and recreate normally.

Logs Excerpted partly because it is too long

I, [2022-09-16T05:23:44.739608 #13225] [task:303801]  INFO -- DirectorJobRunner: sending update deployment error event
D, [2022-09-16T05:23:44.739656 #13225] [task:303801] DEBUG -- DirectorJobRunner: SENT: hm.director.alert {"id":"67e19d45-b8c7-41e3-bed8-cc991986e6b9","severity":3,"source":"director","title":"director - error during update deployment","summary":"Error during update deployment for 'concourse' against Director '8918c85c-4e34-4af1-a19f-3ad5498831a5': #<Bosh::Clouds::ExternalCpi::UnknownError: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-621099')>","created_at":1663305824,"deployment":"concourse"}
D, [2022-09-16T05:23:44.743912 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.001892s) (conn: 47170982356700) BEGIN
D, [2022-09-16T05:23:44.746328 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002135s) (conn: 47170982356700) INSERT INTO `events` (`parent_id`, `timestamp`, `user`, `action`, `object_type`, `object_name`, `error`, `task`, `deployment`, `instance`, `context_json`) VALUES (NULL, '2022-09-16 05:23:44', 'admin', 'create', 'deployment', 'concourse', NULL, '303801', 'concourse', NULL, '{}')
D, [2022-09-16T05:23:44.748575 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002090s) (conn: 47170982356700) SELECT * FROM `events` WHERE `id` = 445610
D, [2022-09-16T05:23:44.754904 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.006201s) (conn: 47170982356700) COMMIT
D, [2022-09-16T05:23:44.759216 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.001898s) (conn: 47170981505980) BEGIN
D, [2022-09-16T05:23:44.761561 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002061s) (conn: 47170981505980) INSERT INTO `events` (`parent_id`, `timestamp`, `user`, `action`, `object_type`, `object_name`, `error`, `task`, `deployment`, `instance`, `context_json`) VALUES (445610, '2022-09-16 05:23:44', 'admin', 'create', 'deployment', 'concourse', 'Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request ID: \'cpi-621099\')', '303801', 'concourse', NULL, '{\"before\":{},\"after\":{\"releases\":[\"bosh-dns/1.27.0\",\"concourse/5.4.0\",\"bpm/1.0.4\",\"postgres/38\"],\"stemcells\":[\"bosh-aws-xen-hvm-ubuntu-xenial-go_agent/315.64\"]}}')
D, [2022-09-16T05:23:44.763752 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002036s) (conn: 47170981505980) SELECT * FROM `events` WHERE `id` = 445611
D, [2022-09-16T05:23:44.769646 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.005769s) (conn: 47170981505980) COMMIT
D, [2022-09-16T05:23:44.775827 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002005s) (conn: 47170982356700) SELECT * FROM `deployments` WHERE (`name` = 'concourse') LIMIT 1
D, [2022-09-16T05:23:44.780322 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002103s) (conn: 47170981505980) SELECT * FROM `variable_sets` WHERE (`variable_sets`.`deployment_id` = 375) ORDER BY `created_at` DESC LIMIT 1
D, [2022-09-16T05:23:44.784391 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.001866s) (conn: 47170982318400) BEGIN
D, [2022-09-16T05:23:44.786678 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002050s) (conn: 47170982318400) UPDATE `variable_sets` SET `writable` = 0 WHERE (`id` = 400) LIMIT 1
D, [2022-09-16T05:23:44.793474 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.006709s) (conn: 47170982318400) COMMIT
D, [2022-09-16T05:23:44.797581 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.001899s) (conn: 47170982356700) BEGIN
D, [2022-09-16T05:23:44.800011 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002194s) (conn: 47170982356700) UPDATE `tasks` SET `event_output` = CONCAT(`event_output`, '{\"time\":1663305824,\"error\":{\"code\":100,\"message\":\"Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request ID: \'cpi-621099\')\"}}\n') WHERE (`id` = 303801)
D, [2022-09-16T05:23:44.806262 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.006176s) (conn: 47170982356700) COMMIT
E, [2022-09-16T05:23:44.806351 #13225] [task:303801] ERROR -- DirectorJobRunner: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-621099')
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi.rb:197:in `handle_error'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi.rb:109:in `invoke_cpi_method'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi.rb:56:in `create_vm'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/cloud/external_cpi_response_wrapper.rb:39:in `create_vm'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/deployment_plan/steps/create_vm_step.rb:139:in `create'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/deployment_plan/steps/create_vm_step.rb:27:in `perform'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:39:in `block in run_agenda'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:36:in `each'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:36:in `run_agenda'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:21:in `block (5 levels) in run'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/event_log.rb:105:in `advance_and_track'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:20:in `block (4 levels) in run'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_formatter.rb:50:in `with_thread_name'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:18:in `block (3 levels) in run'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_pool.rb:77:in `block (2 levels) in create_thread'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_pool.rb:63:in `block in create_thread'
/var/vcap/data/packages/director/d0f423a78a6482fec03562879dd6ee04b1807633/gem_home/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
D, [2022-09-16T05:23:44.810672 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002137s) (conn: 47170981505980) SELECT * FROM `tasks` WHERE `id` = 303801
D, [2022-09-16T05:23:44.814910 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.001895s) (conn: 47170982318400) BEGIN
D, [2022-09-16T05:23:44.817614 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.002305s) (conn: 47170982318400) UPDATE `tasks` SET `state` = 'error', `timestamp` = '2022-09-16 05:23:44', `description` = 'create deployment', `result` = 'Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request...', `output` = '/var/vcap/store/director/tasks/303801', `checkpoint_time` = '2022-09-16 05:23:32', `type` = 'update_deployment', `username` = 'admin', `deployment_name` = 'concourse', `started_at` = '2022-09-16 05:23:02', `event_output` = '{\"time\":1663305783,\"stage\":\"Preparing deployment\",\"tags\":[],\"total\":1,\"task\":\"Preparing deployment\",\"index\":1,\"state\":\"started\",\"progress\":0}\n{\"time\":1663305785,\"stage\":\"Preparing deployment\",\"tags\":[],\"total\":1,\"task\":\"Preparing deployment\",\"index\":1,\"state\":\"finished\",\"progress\":100}\n{\"time\":1663305785,\"stage\":\"Preparing deployment\",\"tags\":[],\"total\":1,\"task\":\"Rendering templates\",\"index\":2,\"state\":\"started\",\"progress\":0}\n{\"time\":1663305787,\"stage\":\"Preparing deployment\",\"tags\":[],\"total\":1,\"task\":\"Rendering templates\",\"index\":2,\"state\":\"finished\",\"progress\":100}\n{\"time\":1663305787,\"stage\":\"Preparing package compilation\",\"tags\":[],\"total\":1,\"task\":\"Finding packages to compile\",\"index\":1,\"state\":\"started\",\"progress\":0}\n{\"time\":1663305787,\"stage\":\"Preparing package compilation\",\"tags\":[],\"total\":1,\"task\":\"Finding packages to compile\",\"index\":1,\"state\":\"finished\",\"progress\":100}\n{\"time\":1663305787,\"stage\":\"Creating missing vms\",\"tags\":[],\"total\":3,\"task\":\"web/aa615f9e-76ce-4c1e-8f91-3b75b0a75044 (0)\",\"index\":1,\"state\":\"started\",\"progress\":0}\n{\"time\":1663305787,\"stage\":\"Creating missing vms\",\"tags\":[],\"total\":3,\"task\":\"db/a1908862-3676-47e1-8e39-f6ada8501c85 (0)\",\"index\":2,\"state\":\"started\",\"progress\":0}\n{\"time\":1663305787,\"stage\":\"Creating missing vms\",\"tags\":[],\"total\":3,\"task\":\"worker/33c3b784-1f2c-4fc1-8d24-bf094f4dae16 (0)\",\"index\":3,\"state\":\"started\",\"progress\":0}\n{\"time\":1663305823,\"stage\":\"Creating missing vms\",\"tags\":[],\"total\":3,\"task\":\"web/aa615f9e-76ce-4c1e-8f91-3b75b0a75044 (0)\",\"index\":1,\"state\":\"failed\",\"progress\":100,\"data\":{\"error\":\"Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request ID: \'cpi-621099\')\"}}\n{\"time\":1663305823,\"stage\":\"Creating missing vms\",\"tags\":[],\"total\":3,\"task\":\"db/a1908862-3676-47e1-8e39-f6ada8501c85 (0)\",\"index\":2,\"state\":\"failed\",\"progress\":100,\"data\":{\"error\":\"Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request ID: \'cpi-683989\')\"}}\n{\"time\":1663305824,\"stage\":\"Creating missing vms\",\"tags\":[],\"total\":3,\"task\":\"worker/33c3b784-1f2c-4fc1-8d24-bf094f4dae16 (0)\",\"index\":3,\"state\":\"failed\",\"progress\":100,\"data\":{\"error\":\"Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request ID: \'cpi-598709\')\"}}\n{\"time\":1663305824,\"error\":{\"code\":100,\"message\":\"Unknown CPI error \'Unknown\' with message \'stopped waiting, encountered a failure state\' in \'create_vm\' CPI method (CPI request ID: \'cpi-621099\')\"}}\n', `result_output` = '', `context_id` = '' WHERE (`id` = 303801) LIMIT 1
D, [2022-09-16T05:23:44.824010 #13225] [task:303801] DEBUG -- DirectorJobRunner: (0.006286s) (conn: 47170982318400) COMMIT
I, [2022-09-16T05:23:44.824142 #13225] []  INFO -- DirectorJobRunner: Task took 42.39101515 seconds to process.

Task 303801 error

Versions (please complete the following information):

rkoster commented 2 years ago

@kwonsoonwoo Could you look if there is any useful context in the cpi log (bosh task _task_id_ --cpi)?

kwonsoonwoo commented 2 years ago 
$ bosh -d concourse recreate --fix
Using environment '10.122.100.6' as client 'admin'

Using deployment 'concourse'

Continue? [yN]: y

Task 319812

Task 319812 | 06:39:08 | Preparing deployment: Preparing deployment (00:00:01)
Task 319812 | 06:39:09 | Preparing deployment: Rendering templates (00:00:03)
Task 319812 | 06:39:12 | Preparing package compilation: Finding packages to compile (00:00:00)
Task 319812 | 06:39:13 | Updating instance worker: worker/acc79b79-12f4-467f-b269-6d8cef01bc0d (0) (canary)
Task 319812 | 06:39:13 | Updating instance web: web/92905f0d-39db-448a-8a90-bd526334cd2d (0) (canary)
Task 319812 | 06:39:13 | Updating instance db: db/5ff4e833-75a2-496d-bceb-f97b1a309996 (0) (canary)
Task 319812 | 06:40:45 | Updating instance web: web/92905f0d-39db-448a-8a90-bd526334cd2d (0) (canary) (00:01:32)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-806584')
Task 319812 | 06:41:09 | Updating instance db: db/5ff4e833-75a2-496d-bceb-f97b1a309996 (0) (canary) (00:01:56)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-150419')
Task 319812 | 06:41:21 | Updating instance worker: worker/acc79b79-12f4-467f-b269-6d8cef01bc0d (0) (canary) (00:02:08)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-787684')
Task 319812 | 06:41:21 | Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-806584')

Task 319812 Started  Fri Sep 23 06:39:08 UTC 2022
Task 319812 Finished Fri Sep 23 06:41:21 UTC 2022
Task 319812 Duration 00:02:13
Task 319812 error

Changing state:
  Expected task '319812' to succeed but state is 'error'

Exit code 1
$ bosh task 319812 --cpi
Using environment '10.122.100.6' as client 'admin'

Task 319812

I, [2022-09-23T06:39:21.252343 #28144]  INFO -- [req_id cpi-180674]: Starting info...
I, [2022-09-23T06:39:21.289427 #28144]  INFO -- [req_id cpi-180674]: Finished info in 0.04 seconds
I, [2022-09-23T06:39:22.314418 #28148]  INFO -- [req_id cpi-146968]: Starting info...
I, [2022-09-23T06:39:22.350490 #28148]  INFO -- [req_id cpi-146968]: Finished info in 0.04 seconds
I, [2022-09-23T06:39:22.709267 #28152]  INFO -- [req_id cpi-920006]: Starting info...
I, [2022-09-23T06:39:22.744327 #28152]  INFO -- [req_id cpi-920006]: Finished info in 0.04 seconds
I, [2022-09-23T06:39:27.249743 #28157]  INFO -- [req_id cpi-752227]: Starting info...
I, [2022-09-23T06:39:27.286374 #28157]  INFO -- [req_id cpi-752227]: Finished info in 0.04 seconds
I, [2022-09-23T06:39:28.705853 #28161]  INFO -- [req_id cpi-559811]: Starting info...
I, [2022-09-23T06:39:28.740404 #28161]  INFO -- [req_id cpi-559811]: Finished info in 0.03 seconds
I, [2022-09-23T06:39:23.740544 #28153]  INFO -- [req_id cpi-570381]: Starting snapshot_disk...
D, [2022-09-23T06:39:23.910540 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.130818 0 retries] describe_volumes(volume_ids:["vol-04608d1ee258d69d5"])

D, [2022-09-23T06:39:24.142194 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.230783 0 retries] create_snapshot(description:"[FILTERED]",volume_id:"vol-04608d1ee258d69d5")

I, [2022-09-23T06:39:24.142367 #28153]  INFO -- [req_id cpi-570381]: snapshot 'snap-05ddb64635087a81e' of volume 'vol-04608d1ee258d69d5' created
I, [2022-09-23T06:39:24.142592 #28153]  INFO -- [req_id cpi-570381]: attempting to tag object: snap-05ddb64635087a81e
D, [2022-09-23T06:39:24.248194 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.104049 0 retries] create_tags(tags:[{key:"deployment",value:"[FILTERED]"},{key:"director_uuid",value:"[FILTERED]"},{key:"agent_id",value:"[FILTERED]"},{key:"instance_id",value:"[FILTERED]"},{key:"GBL_CLASS_0",value:"[FILTERED]"},{key:"GBL_CLASS_1",value:"[FILTERED]"},{key:"SEC_ASSETS",value:"[FILTERED]"},{key:"device",value:"[FILTERED]"},{key:"director",value:"[FILTERED]"},{key:"instance_index",value:"[FILTERED]"},{key:"instance_name",value:"[FILTERED]"},{key:"Name",value:"[FILTERED]"}],resources:["snap-05ddb64635087a81e"])

D, [2022-09-23T06:39:24.347004 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.097811 0 retries] describe_snapshots(snapshot_ids:["snap-05ddb64635087a81e"])

D, [2022-09-23T06:39:24.347146 #28153] DEBUG -- [req_id cpi-570381]: Waiting for snap-05ddb64635087a81e to be completed, retrying in 2 seconds (1/54)
D, [2022-09-23T06:39:26.420456 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.070685 0 retries] describe_snapshots(snapshot_ids:["snap-05ddb64635087a81e"])

D, [2022-09-23T06:39:26.420590 #28153] DEBUG -- [req_id cpi-570381]: Waiting for snap-05ddb64635087a81e to be completed, retrying in 4 seconds (2/54)
D, [2022-09-23T06:39:30.472078 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.047709 0 retries] describe_snapshots(snapshot_ids:["snap-05ddb64635087a81e"])

D, [2022-09-23T06:39:30.472221 #28153] DEBUG -- [req_id cpi-570381]: Waiting for snap-05ddb64635087a81e to be completed, retrying in 8 seconds (3/54)
D, [2022-09-23T06:39:38.560743 #28153] DEBUG -- [req_id cpi-570381]: [Aws::EC2::Client 200 0.080971 0 retries] describe_snapshots(snapshot_ids:["snap-05ddb64635087a81e"])

I, [2022-09-23T06:39:38.560897 #28153]  INFO -- [req_id cpi-570381]: snap-05ddb64635087a81e is now completed, took 14.312374322s
I, [2022-09-23T06:39:38.560978 #28153]  INFO -- [req_id cpi-570381]: Finished snapshot_disk in 14.82 seconds
I, [2022-09-23T06:39:52.015546 #28321]  INFO -- [req_id cpi-208177]: Starting info...
I, [2022-09-23T06:39:52.050302 #28321]  INFO -- [req_id cpi-208177]: Finished info in 0.03 seconds
I, [2022-09-23T06:39:53.420341 #28325]  INFO -- [req_id cpi-803671]: Starting detach_disk...
I, [2022-09-23T06:39:53.454759 #28325]  INFO -- [req_id cpi-803671]: Check the presence of disk with id `vol-04608d1ee258d69d5'...
D, [2022-09-23T06:39:53.580022 #28325] DEBUG -- [req_id cpi-803671]: [Aws::EC2::Client 200 0.12462 0 retries] describe_volumes(volume_ids:["vol-04608d1ee258d69d5"])

D, [2022-09-23T06:39:53.680913 #28325] DEBUG -- [req_id cpi-803671]: [Aws::EC2::Client 200 0.100287 0 retries] describe_instances(instance_ids:["i-038767b815d715598"])

D, [2022-09-23T06:39:54.051400 #28325] DEBUG -- [req_id cpi-803671]: [Aws::EC2::Client 200 0.369849 0 retries] detach_volume(instance_id:"i-038767b815d715598",device:"/dev/sdf",force:false,volume_id:"vol-04608d1ee258d69d5")

I, [2022-09-23T06:39:54.051520 #28325]  INFO -- [req_id cpi-803671]: Detaching `vol-04608d1ee258d69d5' from `i-038767b815d715598'
D, [2022-09-23T06:39:54.137157 #28325] DEBUG -- [req_id cpi-803671]: [Aws::EC2::Client 200 0.084989 0 retries] describe_volumes(volume_ids:["vol-04608d1ee258d69d5"])

D, [2022-09-23T06:39:54.137321 #28325] DEBUG -- [req_id cpi-803671]: Waiting for volume vol-04608d1ee258d69d5 to be detached to instance i-038767b815d715598 as device /dev/sdf to be detached, retrying in 2 seconds (1/54)
D, [2022-09-23T06:39:56.232263 #28325] DEBUG -- [req_id cpi-803671]: [Aws::EC2::Client 200 0.092322 0 retries] describe_volumes(volume_ids:["vol-04608d1ee258d69d5"])

D, [2022-09-23T06:39:56.232416 #28325] DEBUG -- [req_id cpi-803671]: Waiting for volume vol-04608d1ee258d69d5 to be detached to instance i-038767b815d715598 as device /dev/sdf to be detached, retrying in 4 seconds (2/54)
D, [2022-09-23T06:40:00.340190 #28325] DEBUG -- [req_id cpi-803671]: [Aws::EC2::Client 200 0.103122 0 retries] describe_volumes(volume_ids:["vol-04608d1ee258d69d5"])

I, [2022-09-23T06:40:00.340479 #28325]  INFO -- [req_id cpi-803671]: Detached `vol-04608d1ee258d69d5' from `i-038767b815d715598'
I, [2022-09-23T06:40:00.340565 #28325]  INFO -- [req_id cpi-803671]: Finished detach_disk in 6.92 seconds
I, [2022-09-23T06:40:01.818807 #28329]  INFO -- [req_id cpi-691782]: Starting info...
I, [2022-09-23T06:40:01.856968 #28329]  INFO -- [req_id cpi-691782]: Finished info in 0.04 seconds
I, [2022-09-23T06:39:24.136978 #28154]  INFO -- [req_id cpi-981236]: Starting delete_vm...
I, [2022-09-23T06:39:24.175025 #28154]  INFO -- [req_id cpi-981236]: Deleting instance 'i-08e4b38fe4234ded8'
D, [2022-09-23T06:39:24.412893 #28154] DEBUG -- [req_id cpi-981236]: [Aws::EC2::Client 200 0.237237 0 retries] terminate_instances(instance_ids:["i-08e4b38fe4234ded8"])

I, [2022-09-23T06:39:24.413012 #28154]  INFO -- [req_id cpi-981236]: Deleting instance settings for 'i-08e4b38fe4234ded8'
I, [2022-09-23T06:39:24.413052 #28154]  INFO -- [req_id cpi-981236]: Deleting instance 'i-08e4b38fe4234ded8'
D, [2022-09-23T06:39:24.547750 #28154] DEBUG -- [req_id cpi-981236]: [Aws::EC2::Client 200 0.134116 0 retries] describe_instances(instance_ids:["i-08e4b38fe4234ded8"])

D, [2022-09-23T06:39:39.737125 #28154] DEBUG -- [req_id cpi-981236]: [Aws::EC2::Client 200 0.173377 0 retries] describe_instances(instance_ids:["i-08e4b38fe4234ded8"])

D, [2022-09-23T06:39:54.928262 #28154] DEBUG -- [req_id cpi-981236]: [Aws::EC2::Client 200 0.174808 0 retries] describe_instances(instance_ids:["i-08e4b38fe4234ded8"])

D, [2022-09-23T06:40:10.033740 #28154] DEBUG -- [req_id cpi-981236]: [Aws::EC2::Client 200 0.093925 0 retries] describe_instances(instance_ids:["i-08e4b38fe4234ded8"])

I, [2022-09-23T06:40:10.034238 #28154]  INFO -- [req_id cpi-981236]: Finished delete_vm in 45.9 seconds
I, [2022-09-23T06:40:12.073584 #28334]  INFO -- [req_id cpi-186786]: Starting info...
I, [2022-09-23T06:40:12.111148 #28334]  INFO -- [req_id cpi-186786]: Finished info in 0.04 seconds
I, [2022-09-23T06:40:03.289403 #28331]  INFO -- [req_id cpi-861389]: Starting delete_vm...
I, [2022-09-23T06:40:03.327294 #28331]  INFO -- [req_id cpi-861389]: Deleting instance 'i-038767b815d715598'
D, [2022-09-23T06:40:03.642491 #28331] DEBUG -- [req_id cpi-861389]: [Aws::EC2::Client 200 0.314571 0 retries] terminate_instances(instance_ids:["i-038767b815d715598"])

I, [2022-09-23T06:40:03.642626 #28331]  INFO -- [req_id cpi-861389]: Deleting instance settings for 'i-038767b815d715598'
I, [2022-09-23T06:40:03.642668 #28331]  INFO -- [req_id cpi-861389]: Deleting instance 'i-038767b815d715598'
D, [2022-09-23T06:40:03.787075 #28331] DEBUG -- [req_id cpi-861389]: [Aws::EC2::Client 200 0.143812 0 retries] describe_instances(instance_ids:["i-038767b815d715598"])

D, [2022-09-23T06:40:18.936867 #28331] DEBUG -- [req_id cpi-861389]: [Aws::EC2::Client 200 0.137125 0 retries] describe_instances(instance_ids:["i-038767b815d715598"])

D, [2022-09-23T06:40:34.022595 #28331] DEBUG -- [req_id cpi-861389]: [Aws::EC2::Client 200 0.072515 0 retries] describe_instances(instance_ids:["i-038767b815d715598"])

I, [2022-09-23T06:40:34.023074 #28331]  INFO -- [req_id cpi-861389]: Finished delete_vm in 30.73 seconds
I, [2022-09-23T06:40:35.886442 #28342]  INFO -- [req_id cpi-752048]: Starting info...
I, [2022-09-23T06:40:35.920484 #28342]  INFO -- [req_id cpi-752048]: Finished info in 0.03 seconds
Rescued Unknown: stopped waiting, encountered a failure state. backtrace: /var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:111:in `block in poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `loop'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:92:in `block (2 levels) in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `block in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/waiters.rb:484:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/instance.rb:369:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance.rb:65:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:69:in `babysit_instance_creation'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:42:in `create'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_core.rb:89:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:64:in `block in create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:51:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `public_send'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `run'
/var/vcap/packages/bosh_aws_cpi/bin/aws_cpi:28:in `<top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `kernel_load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in `exec'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:in `block in <top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in `<top (required)>'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `load'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `<main>'I, [2022-09-23T06:40:13.526454 #28336]  INFO -- [req_id cpi-806584]: Starting create_vm...
D, [2022-09-23T06:40:13.653532 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.088954 0 retries] describe_images(image_ids:["ami-0a32db245df5057c9"])

D, [2022-09-23T06:40:13.725661 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.071163 0 retries] describe_images(image_ids:["ami-0a32db245df5057c9"])

D, [2022-09-23T06:40:13.725826 #28336] DEBUG -- [req_id cpi-806584]: Use EBS storage to create the virtual machine
I, [2022-09-23T06:40:13.725970 #28336]  INFO -- [req_id cpi-806584]: Mapping device {:device_name=>"/dev/sdb", :ebs=>{:volume_size=>20, :volume_type=>"gp2", :delete_on_termination=>true, :encrypted=>true, :kms_key_id=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}, :bosh_type=>"ephemeral"} to path: "/dev/sdb"
I, [2022-09-23T06:40:13.726018 #28336]  INFO -- [req_id cpi-806584]: Mapping device {:device_name=>"/dev/xvda", :ebs=>{:volume_type=>"gp2", :delete_on_termination=>true}} to path: "/dev/xvda"
D, [2022-09-23T06:40:13.872375 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.145447 0 retries] describe_subnets(filters:[{name:"[FILTERED]",values:"[FILTERED]"}])

D, [2022-09-23T06:40:13.965252 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.092128 0 retries] describe_subnets(subnet_ids:["subnet-0b1ea5a9d314e553f"])

D, [2022-09-23T06:40:14.179072 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.213097 0 retries] describe_security_groups(filters:[{name:"[FILTERED]",values:"[FILTERED]"}])

I, [2022-09-23T06:40:14.180016 #28336]  INFO -- [req_id cpi-806584]: Creating new instance with: {"image_id"=>"ami-0a32db245df5057c9", "instance_type"=>"t3.small", "key_name"=>"cf-stg", "user_data"=>"<redacted>", "block_device_mappings"=>[{"device_name"=>"/dev/sdb", "ebs"=>{"volume_size"=>20, "volume_type"=>"gp2", "delete_on_termination"=>true, "encrypted"=>true, "kms_key_id"=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}}, {"device_name"=>"/dev/xvda", "ebs"=>{"volume_type"=>"gp2", "delete_on_termination"=>true}}], "tag_specifications"=>[{"resource_type"=>"instance", "tags"=>[{"key"=>"GBL_CLASS_0", "value"=>"OPERATION"}, {"key"=>"GBL_CLASS_1", "value"=>"TEST"}, {"key"=>"SEC_ASSETS", "value"=>"scf"}]}], "placement"=>{"availability_zone"=>"ap-northeast-1a"}, "network_interfaces"=>[{"groups"=>["sg-06c341a31813f550c", "sg-023b0c80cc3bdb331"], "subnet_id"=>"subnet-0b1ea5a9d314e553f", "device_index"=>0}]}
I, [2022-09-23T06:40:14.180078 #28336]  INFO -- [req_id cpi-806584]: Launching spot instance...
D, [2022-09-23T06:40:14.180505 #28336] DEBUG -- [req_id cpi-806584]: Requesting spot instance with: {"spot_price"=>"0.03", "instance_count"=>1, "launch_specification"=>{"image_id"=>"ami-0a32db245df5057c9", "instance_type"=>"t3.small", "key_name"=>"cf-stg", "user_data"=>"<redacted>", "block_device_mappings"=>[{"device_name"=>"/dev/sdb", "ebs"=>{"volume_size"=>20, "volume_type"=>"gp2", "delete_on_termination"=>true, "encrypted"=>true, "kms_key_id"=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}}, {"device_name"=>"/dev/xvda", "ebs"=>{"volume_type"=>"gp2", "delete_on_termination"=>true}}], "placement"=>{"availability_zone"=>"ap-northeast-1a"}, "network_interfaces"=>[{"groups"=>["sg-06c341a31813f550c", "sg-023b0c80cc3bdb331"], "subnet_id"=>"subnet-0b1ea5a9d314e553f", "device_index"=>0}]}}
D, [2022-09-23T06:40:15.050363 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.868848 0 retries] request_spot_instances(spot_price:"0.03",instance_count:1,launch_specification:{image_id:"ami-0a32db245df5057c9",instance_type:"t3.small",key_name:"cf-stg",user_data:#<String "eyJ2bSI6eyJuYW1lIjoidm0tZDIxMWRjNzEtOTc3Ny00OWFjLTlkZDctZGVk\nYTkwMTUwZjdjIn0sImFnZW50X2lkIjoiMzUzNWZiMjEtMmRhYS00YmQ4LWE1\nMGEtMDM3NTViNzRjMjY4IiwibmV0d29ya3MiOnsic2VydmljZSI6eyJ0eXBl\nIjoiZHluYW1pYyIsImNsb3VkX3Byb3BlcnRpZXMiOnsic2VjdXJpdHlfZ3Jv\ndXBzIjpbImNmLXN0Zy1ib3NoIiwiY2Ytc3RnLXBhY2thZ2VzIl0sInN1Ym5l\ndCI6InN1Ym5ldC0wYjFlYTVhOWQzMTRlNTUzZiJ9LCJkZWZhdWx0IjpbImRu\ncyIsImdhdGV3YXkiXSwiaXAiOiIxMC4xMjIuMTAwLjY4IiwibmV0bWFzayI6\nIjI1NS4yNTUuMjU1LjAiLCJnYXRld2F5IjoiMTAuMTIyLjEwMC4xIiwidXNl\nX2RoY3AiOnRydWV9fSwiZGlza3MiOnsic3lzdGVtIjoiL2Rldi94dmRhIiwi\ncGVyc2lzdGVudCI6e30sImVwaGVtZXJhbCI6Ii9kZXYvc2RiIn0sImVudiI6\neyJib3NoIjp7ImJsb2JzdG9yZXMiOlt7Im9wdGlvbnMiOnsiYWNjZXNzX2tl\neV9pZCI6IkFLSUEyVE9XVUpPQU9UVFZWQ0wyIiwiYnVja2V0X25hbWUiOiJj\nZi1zdGctYmxvYnN0b3JlLWJvc2giLCJyZWdpb24iOiJhcC1ub3J0aGVhc3Qt\nMSIsInNlY3JldF9hY2Nlc3Nfa2V5IjoiVmo3VUZqSWY0TGZwSE9UQWlGNVd1\na2dZeU0yZzZNNTE3bXU4WXQ5WCJ9LCJwcm92aWRlciI6InMzIn1dLCJudHAi\nOlsiMTY5LjI1NC4xNjkuMTIzIiwidGltZTEuZ29vZ2xlLmNvbSIsInRpbWUy\nLmdvb2dsZS5jb20iLCJ0aW1l" ... (9247 bytes)>,block_device_mappings:[{device_name:"/dev/sdb",ebs:{volume_size:20,volume_type:"gp2",delete_on_termination:true,encrypted:true,kms_key_id:"[FILTERED]"}},{device_name:"/dev/xvda",ebs:{volume_type:"gp2",delete_on_termination:true}}],placement:{availability_zone:"ap-northeast-1a"},network_interfaces:[{groups:["sg-06c341a31813f550c","sg-023b0c80cc3bdb331"],subnet_id:"subnet-0b1ea5a9d314e553f",device_index:0}]})

D, [2022-09-23T06:40:15.050677 #28336] DEBUG -- [req_id cpi-806584]: Got spot instance requests: #<struct Aws::EC2::Types::RequestSpotInstancesResult spot_instance_requests=[#<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:14 UTC, fault=nil, instance_id=nil, launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="default", group_id=nil>], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0b1ea5a9d314e553f">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone=nil, product_description="Linux/UNIX", spot_instance_request_id="sir-wi4yedxg", spot_price="0.030000", state="open", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="pending-evaluation", message="Your Spot request has been submitted for review, and is pending evaluation.", update_time=2022-09-23 06:40:14 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=nil, instance_interruption_behavior="terminate">]>
D, [2022-09-23T06:40:15.050801 #28336] DEBUG -- [req_id cpi-806584]: Checking state of spot instance requests...
D, [2022-09-23T06:40:15.089116 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 400 0.037787 0 retries] describe_spot_instance_requests(spot_instance_request_ids:["sir-wi4yedxg"]) Aws::EC2::Errors::InvalidSpotInstanceRequestIDNotFound The spot instance request ID 'sir-wi4yedxg' does not exist

W, [2022-09-23T06:40:45.107236 #28336]  WARN -- [req_id cpi-806584]: Retrying after expected error: The spot instance request ID 'sir-wi4yedxg' does not exist
D, [2022-09-23T06:40:45.107327 #28336] DEBUG -- [req_id cpi-806584]: Checking state of spot instance requests...
D, [2022-09-23T06:40:45.211914 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.104018 0 retries] describe_spot_instance_requests(spot_instance_request_ids:["sir-wi4yedxg"])

D, [2022-09-23T06:40:45.212224 #28336] DEBUG -- [req_id cpi-806584]: Spot instance request status: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:14 UTC, fault=nil, instance_id="i-01f76aaab1464a92b", launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh", group_id="sg-06c341a31813f550c">, #<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-packages", group_id="sg-023b0c80cc3bdb331">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0b1ea5a9d314e553f">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-wi4yedxg", spot_price="0.030000", state="active", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="fulfilled", message="Your spot request is fulfilled.", update_time=2022-09-23 06:40:16 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:14 UTC, instance_interruption_behavior="terminate">
I, [2022-09-23T06:40:45.212428 #28336]  INFO -- [req_id cpi-806584]: Spot request instances fulfilled: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:14 UTC, fault=nil, instance_id="i-01f76aaab1464a92b", launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh", group_id="sg-06c341a31813f550c">, #<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-packages", group_id="sg-023b0c80cc3bdb331">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0b1ea5a9d314e553f">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-wi4yedxg", spot_price="0.030000", state="active", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="fulfilled", message="Your spot request is fulfilled.", update_time=2022-09-23 06:40:16 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:14 UTC, instance_interruption_behavior="terminate">
I, [2022-09-23T06:40:45.212600 #28336]  INFO -- [req_id cpi-806584]: attempting to tag object: i-01f76aaab1464a92b
D, [2022-09-23T06:40:45.407122 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.193851 0 retries] create_tags(tags:[{key:"GBL_CLASS_0",value:"[FILTERED]"},{key:"GBL_CLASS_1",value:"[FILTERED]"},{key:"SEC_ASSETS",value:"[FILTERED]"}],resources:["i-01f76aaab1464a92b"])

I, [2022-09-23T06:40:45.407329 #28336]  INFO -- [req_id cpi-806584]: Waiting for instance to exist...
D, [2022-09-23T06:40:45.476439 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.068509 0 retries] describe_instances(instance_ids:["i-01f76aaab1464a92b"])

I, [2022-09-23T06:40:45.476862 #28336]  INFO -- [req_id cpi-806584]: Waiting for instance to be ready...
D, [2022-09-23T06:40:45.524219 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.046778 0 retries] describe_instances(instance_ids:["i-01f76aaab1464a92b"])

W, [2022-09-23T06:40:45.525032 #28336]  WARN -- [req_id cpi-806584]: Failed to configure instance 'i-01f76aaab1464a92b': #<Aws::Waiters::Errors::FailureStateError: stopped waiting, encountered a failure state>
D, [2022-09-23T06:40:45.669395 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.143849 0 retries] terminate_instances(instance_ids:["i-01f76aaab1464a92b"])

I, [2022-09-23T06:40:45.669524 #28336]  INFO -- [req_id cpi-806584]: Deleting instance settings for 'i-01f76aaab1464a92b'
I, [2022-09-23T06:40:45.669568 #28336]  INFO -- [req_id cpi-806584]: Deleting instance 'i-01f76aaab1464a92b'
D, [2022-09-23T06:40:45.722679 #28336] DEBUG -- [req_id cpi-806584]: [Aws::EC2::Client 200 0.052541 0 retries] describe_instances(instance_ids:["i-01f76aaab1464a92b"])

E, [2022-09-23T06:40:45.723215 #28336] ERROR -- [req_id cpi-806584]: Failed to create instance: stopped waiting, encountered a failure state
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:111:in `block in poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `loop'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:92:in `block (2 levels) in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `block in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/waiters.rb:484:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/instance.rb:369:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance.rb:65:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:69:in `babysit_instance_creation'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:42:in `create'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_core.rb:89:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:64:in `block in create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:51:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `public_send'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `run'
/var/vcap/packages/bosh_aws_cpi/bin/aws_cpi:28:in `<top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `kernel_load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in `exec'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:in `block in <top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in `<top (required)>'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `load'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `<main>'
I, [2022-09-23T06:40:45.723471 #28336]  INFO -- [req_id cpi-806584]: Finished create_vm in 32.2 seconds
I, [2022-09-23T06:39:30.123207 #28162]  INFO -- [req_id cpi-904618]: Starting delete_vm...
I, [2022-09-23T06:39:30.158005 #28162]  INFO -- [req_id cpi-904618]: Deleting instance 'i-031afb64f01976d18'
D, [2022-09-23T06:39:30.362793 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.204172 0 retries] terminate_instances(instance_ids:["i-031afb64f01976d18"])

I, [2022-09-23T06:39:30.362922 #28162]  INFO -- [req_id cpi-904618]: Deleting instance settings for 'i-031afb64f01976d18'
I, [2022-09-23T06:39:30.362961 #28162]  INFO -- [req_id cpi-904618]: Deleting instance 'i-031afb64f01976d18'
D, [2022-09-23T06:39:30.511036 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.14747 0 retries] describe_instances(instance_ids:["i-031afb64f01976d18"])

D, [2022-09-23T06:39:45.665248 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.137784 0 retries] describe_instances(instance_ids:["i-031afb64f01976d18"])

D, [2022-09-23T06:40:00.823729 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.151973 0 retries] describe_instances(instance_ids:["i-031afb64f01976d18"])

D, [2022-09-23T06:40:15.949323 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.109218 0 retries] describe_instances(instance_ids:["i-031afb64f01976d18"])

D, [2022-09-23T06:40:31.057494 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.094993 0 retries] describe_instances(instance_ids:["i-031afb64f01976d18"])

D, [2022-09-23T06:40:46.164445 #28162] DEBUG -- [req_id cpi-904618]: [Aws::EC2::Client 200 0.090617 0 retries] describe_instances(instance_ids:["i-031afb64f01976d18"])

I, [2022-09-23T06:40:46.164916 #28162]  INFO -- [req_id cpi-904618]: Finished delete_vm in 76.04 seconds
I, [2022-09-23T06:40:47.780891 #28349]  INFO -- [req_id cpi-960508]: Starting info...
I, [2022-09-23T06:40:47.815606 #28349]  INFO -- [req_id cpi-960508]: Finished info in 0.03 seconds
Rescued Unknown: stopped waiting, encountered a failure state. backtrace: /var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:111:in `block in poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `loop'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:92:in `block (2 levels) in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `block in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/waiters.rb:484:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/instance.rb:369:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance.rb:65:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:69:in `babysit_instance_creation'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:42:in `create'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_core.rb:89:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:64:in `block in create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:51:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `public_send'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `run'
/var/vcap/packages/bosh_aws_cpi/bin/aws_cpi:28:in `<top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `kernel_load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in `exec'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:in `block in <top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in `<top (required)>'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `load'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `<main>'I, [2022-09-23T06:40:37.287846 #28344]  INFO -- [req_id cpi-150419]: Starting create_vm...
D, [2022-09-23T06:40:37.406059 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.080459 0 retries] describe_images(image_ids:["ami-0a32db245df5057c9"])

D, [2022-09-23T06:40:37.476631 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.069635 0 retries] describe_images(image_ids:["ami-0a32db245df5057c9"])

D, [2022-09-23T06:40:37.476783 #28344] DEBUG -- [req_id cpi-150419]: Use EBS storage to create the virtual machine
I, [2022-09-23T06:40:37.476924 #28344]  INFO -- [req_id cpi-150419]: Mapping device {:device_name=>"/dev/sdb", :ebs=>{:volume_size=>20, :volume_type=>"gp2", :delete_on_termination=>true, :encrypted=>true, :kms_key_id=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}, :bosh_type=>"ephemeral"} to path: "/dev/sdb"
I, [2022-09-23T06:40:37.476972 #28344]  INFO -- [req_id cpi-150419]: Mapping device {:device_name=>"/dev/xvda", :ebs=>{:volume_type=>"gp2", :delete_on_termination=>true}} to path: "/dev/xvda"
D, [2022-09-23T06:40:37.544010 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.066208 0 retries] describe_volumes(volume_ids:["vol-04608d1ee258d69d5"])

D, [2022-09-23T06:40:37.669532 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.124843 0 retries] describe_subnets(filters:[{name:"[FILTERED]",values:"[FILTERED]"}])

D, [2022-09-23T06:40:37.735630 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.06536 0 retries] describe_subnets(subnet_ids:["subnet-0fbc17eb6c5567135"])

D, [2022-09-23T06:40:37.976226 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.23989 0 retries] describe_security_groups(filters:[{name:"[FILTERED]",values:"[FILTERED]"}])

I, [2022-09-23T06:40:37.983053 #28344]  INFO -- [req_id cpi-150419]: Creating new instance with: {"image_id"=>"ami-0a32db245df5057c9", "instance_type"=>"t3.small", "key_name"=>"cf-stg", "user_data"=>"<redacted>", "block_device_mappings"=>[{"device_name"=>"/dev/sdb", "ebs"=>{"volume_size"=>20, "volume_type"=>"gp2", "delete_on_termination"=>true, "encrypted"=>true, "kms_key_id"=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}}, {"device_name"=>"/dev/xvda", "ebs"=>{"volume_type"=>"gp2", "delete_on_termination"=>true}}], "tag_specifications"=>[{"resource_type"=>"instance", "tags"=>[{"key"=>"GBL_CLASS_0", "value"=>"OPERATION"}, {"key"=>"GBL_CLASS_1", "value"=>"TEST"}, {"key"=>"SEC_ASSETS", "value"=>"scf"}]}], "placement"=>{"availability_zone"=>"ap-northeast-1a"}, "network_interfaces"=>[{"groups"=>["sg-08e1b7d95cb60742b"], "subnet_id"=>"subnet-0fbc17eb6c5567135", "device_index"=>0}]}
I, [2022-09-23T06:40:37.983127 #28344]  INFO -- [req_id cpi-150419]: Launching spot instance...
D, [2022-09-23T06:40:37.983566 #28344] DEBUG -- [req_id cpi-150419]: Requesting spot instance with: {"spot_price"=>"0.03", "instance_count"=>1, "launch_specification"=>{"image_id"=>"ami-0a32db245df5057c9", "instance_type"=>"t3.small", "key_name"=>"cf-stg", "user_data"=>"<redacted>", "block_device_mappings"=>[{"device_name"=>"/dev/sdb", "ebs"=>{"volume_size"=>20, "volume_type"=>"gp2", "delete_on_termination"=>true, "encrypted"=>true, "kms_key_id"=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}}, {"device_name"=>"/dev/xvda", "ebs"=>{"volume_type"=>"gp2", "delete_on_termination"=>true}}], "placement"=>{"availability_zone"=>"ap-northeast-1a"}, "network_interfaces"=>[{"groups"=>["sg-08e1b7d95cb60742b"], "subnet_id"=>"subnet-0fbc17eb6c5567135", "device_index"=>0}]}}
D, [2022-09-23T06:40:38.828784 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.844217 0 retries] request_spot_instances(spot_price:"0.03",instance_count:1,launch_specification:{image_id:"ami-0a32db245df5057c9",instance_type:"t3.small",key_name:"cf-stg",user_data:#<String "eyJ2bSI6eyJuYW1lIjoidm0tODU3NDFmYjktZDQ4ZS00OTRhLWE5YTUtMThk\nMDAzMzg0NTcyIn0sImFnZW50X2lkIjoiM2EwNjg4ZjUtNmIyNS00ZGJlLTk4\nZDItZTdhNDE0ZTEyNGI4IiwibmV0d29ya3MiOnsiZGIiOnsidHlwZSI6ImR5\nbmFtaWMiLCJjbG91ZF9wcm9wZXJ0aWVzIjp7InNlY3VyaXR5X2dyb3VwcyI6\nWyJjZi1zdGctYm9zaC1kYiJdLCJzdWJuZXQiOiJzdWJuZXQtMGZiYzE3ZWI2\nYzU1NjcxMzUifSwiZGVmYXVsdCI6WyJkbnMiLCJnYXRld2F5Il0sImlwIjoi\nMTAuMTIyLjMuMjM2IiwibmV0bWFzayI6IjI1NS4yNTUuMjU1LjAiLCJnYXRl\nd2F5IjoiMTAuMTIyLjMuMSIsInVzZV9kaGNwIjp0cnVlfX0sImRpc2tzIjp7\nInN5c3RlbSI6Ii9kZXYveHZkYSIsInBlcnNpc3RlbnQiOnt9LCJlcGhlbWVy\nYWwiOiIvZGV2L3NkYiJ9LCJlbnYiOnsiYm9zaCI6eyJibG9ic3RvcmVzIjpb\neyJvcHRpb25zIjp7ImFjY2Vzc19rZXlfaWQiOiJBS0lBMlRPV1VKT0FPVFRW\nVkNMMiIsImJ1Y2tldF9uYW1lIjoiY2Ytc3RnLWJsb2JzdG9yZS1ib3NoIiwi\ncmVnaW9uIjoiYXAtbm9ydGhlYXN0LTEiLCJzZWNyZXRfYWNjZXNzX2tleSI6\nIlZqN1VGaklmNExmcEhPVEFpRjVXdWtnWXlNMmc2TTUxN211OFl0OVgifSwi\ncHJvdmlkZXIiOiJzMyJ9XSwibnRwIjpbIjE2OS4yNTQuMTY5LjEyMyIsInRp\nbWUxLmdvb2dsZS5jb20iLCJ0aW1lMi5nb29nbGUuY29tIiwidGltZTMuZ29v\nZ2xlLmNvbSIsInRpbWU0Lmdv" ... (9215 bytes)>,block_device_mappings:[{device_name:"/dev/sdb",ebs:{volume_size:20,volume_type:"gp2",delete_on_termination:true,encrypted:true,kms_key_id:"[FILTERED]"}},{device_name:"/dev/xvda",ebs:{volume_type:"gp2",delete_on_termination:true}}],placement:{availability_zone:"ap-northeast-1a"},network_interfaces:[{groups:["sg-08e1b7d95cb60742b"],subnet_id:"subnet-0fbc17eb6c5567135",device_index:0}]})

D, [2022-09-23T06:40:38.829093 #28344] DEBUG -- [req_id cpi-150419]: Got spot instance requests: #<struct Aws::EC2::Types::RequestSpotInstancesResult spot_instance_requests=[#<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:38 UTC, fault=nil, instance_id=nil, launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="default", group_id=nil>], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0fbc17eb6c5567135">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone=nil, product_description="Linux/UNIX", spot_instance_request_id="sir-76dpep3k", spot_price="0.030000", state="open", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="pending-evaluation", message="Your Spot request has been submitted for review, and is pending evaluation.", update_time=2022-09-23 06:40:38 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=nil, instance_interruption_behavior="terminate">]>
D, [2022-09-23T06:40:38.829212 #28344] DEBUG -- [req_id cpi-150419]: Checking state of spot instance requests...
D, [2022-09-23T06:40:38.895427 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.065701 0 retries] describe_spot_instance_requests(spot_instance_request_ids:["sir-76dpep3k"])

D, [2022-09-23T06:40:38.895727 #28344] DEBUG -- [req_id cpi-150419]: Spot instance request status: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:38 UTC, fault=nil, instance_id=nil, launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh-db", group_id="sg-08e1b7d95cb60742b">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0fbc17eb6c5567135">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-76dpep3k", spot_price="0.030000", state="open", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="pending-fulfillment", message="Your Spot request is pending fulfillment.", update_time=2022-09-23 06:40:38 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:38 UTC, instance_interruption_behavior="terminate">
D, [2022-09-23T06:41:08.921724 #28344] DEBUG -- [req_id cpi-150419]: Checking state of spot instance requests...
D, [2022-09-23T06:41:09.034099 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.111741 0 retries] describe_spot_instance_requests(spot_instance_request_ids:["sir-76dpep3k"])

D, [2022-09-23T06:41:09.034390 #28344] DEBUG -- [req_id cpi-150419]: Spot instance request status: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:38 UTC, fault=nil, instance_id="i-07e2ad9430b901aae", launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh-db", group_id="sg-08e1b7d95cb60742b">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0fbc17eb6c5567135">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-76dpep3k", spot_price="0.030000", state="active", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="fulfilled", message="Your spot request is fulfilled.", update_time=2022-09-23 06:40:40 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:38 UTC, instance_interruption_behavior="terminate">
I, [2022-09-23T06:41:09.034581 #28344]  INFO -- [req_id cpi-150419]: Spot request instances fulfilled: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:38 UTC, fault=nil, instance_id="i-07e2ad9430b901aae", launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh-db", group_id="sg-08e1b7d95cb60742b">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=20, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.small", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-0fbc17eb6c5567135">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-76dpep3k", spot_price="0.030000", state="active", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="fulfilled", message="Your spot request is fulfilled.", update_time=2022-09-23 06:40:40 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:38 UTC, instance_interruption_behavior="terminate">
I, [2022-09-23T06:41:09.034755 #28344]  INFO -- [req_id cpi-150419]: attempting to tag object: i-07e2ad9430b901aae
D, [2022-09-23T06:41:09.201540 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.166102 0 retries] create_tags(tags:[{key:"GBL_CLASS_0",value:"[FILTERED]"},{key:"GBL_CLASS_1",value:"[FILTERED]"},{key:"SEC_ASSETS",value:"[FILTERED]"}],resources:["i-07e2ad9430b901aae"])

I, [2022-09-23T06:41:09.201715 #28344]  INFO -- [req_id cpi-150419]: Waiting for instance to exist...
D, [2022-09-23T06:41:09.272937 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.07064 0 retries] describe_instances(instance_ids:["i-07e2ad9430b901aae"])

I, [2022-09-23T06:41:09.273331 #28344]  INFO -- [req_id cpi-150419]: Waiting for instance to be ready...
D, [2022-09-23T06:41:09.331170 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.057257 0 retries] describe_instances(instance_ids:["i-07e2ad9430b901aae"])

W, [2022-09-23T06:41:09.331957 #28344]  WARN -- [req_id cpi-150419]: Failed to configure instance 'i-07e2ad9430b901aae': #<Aws::Waiters::Errors::FailureStateError: stopped waiting, encountered a failure state>
D, [2022-09-23T06:41:09.488805 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.156343 0 retries] terminate_instances(instance_ids:["i-07e2ad9430b901aae"])

I, [2022-09-23T06:41:09.488917 #28344]  INFO -- [req_id cpi-150419]: Deleting instance settings for 'i-07e2ad9430b901aae'
I, [2022-09-23T06:41:09.488955 #28344]  INFO -- [req_id cpi-150419]: Deleting instance 'i-07e2ad9430b901aae'
D, [2022-09-23T06:41:09.547703 #28344] DEBUG -- [req_id cpi-150419]: [Aws::EC2::Client 200 0.058186 0 retries] describe_instances(instance_ids:["i-07e2ad9430b901aae"])

E, [2022-09-23T06:41:09.548226 #28344] ERROR -- [req_id cpi-150419]: Failed to create instance: stopped waiting, encountered a failure state
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:111:in `block in poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `loop'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:92:in `block (2 levels) in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `block in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/waiters.rb:484:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/instance.rb:369:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance.rb:65:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:69:in `babysit_instance_creation'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:42:in `create'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_core.rb:89:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:64:in `block in create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:51:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `public_send'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `run'
/var/vcap/packages/bosh_aws_cpi/bin/aws_cpi:28:in `<top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `kernel_load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in `exec'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:in `block in <top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in `<top (required)>'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `load'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `<main>'
I, [2022-09-23T06:41:09.548465 #28344]  INFO -- [req_id cpi-150419]: Finished create_vm in 32.26 seconds
Rescued Unknown: stopped waiting, encountered a failure state. backtrace: /var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:111:in `block in poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `loop'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:92:in `block (2 levels) in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `block in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/waiters.rb:484:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/instance.rb:369:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance.rb:65:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:69:in `babysit_instance_creation'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:42:in `create'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_core.rb:89:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:64:in `block in create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:51:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `public_send'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `run'
/var/vcap/packages/bosh_aws_cpi/bin/aws_cpi:28:in `<top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `kernel_load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in `exec'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:in `block in <top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in `<top (required)>'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `load'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `<main>'I, [2022-09-23T06:40:49.190788 #28350]  INFO -- [req_id cpi-787684]: Starting create_vm...
D, [2022-09-23T06:40:49.293071 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.064069 0 retries] describe_images(image_ids:["ami-0a32db245df5057c9"])

D, [2022-09-23T06:40:49.356721 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.062697 0 retries] describe_images(image_ids:["ami-0a32db245df5057c9"])

D, [2022-09-23T06:40:49.356878 #28350] DEBUG -- [req_id cpi-787684]: Use EBS storage to create the virtual machine
I, [2022-09-23T06:40:49.357022 #28350]  INFO -- [req_id cpi-787684]: Mapping device {:device_name=>"/dev/sdb", :ebs=>{:volume_size=>49, :volume_type=>"gp2", :delete_on_termination=>true, :encrypted=>true, :kms_key_id=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}, :bosh_type=>"ephemeral"} to path: "/dev/sdb"
I, [2022-09-23T06:40:49.357074 #28350]  INFO -- [req_id cpi-787684]: Mapping device {:device_name=>"/dev/xvda", :ebs=>{:volume_type=>"gp2", :delete_on_termination=>true}} to path: "/dev/xvda"
D, [2022-09-23T06:40:49.460042 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.102034 0 retries] describe_subnets(filters:[{name:"[FILTERED]",values:"[FILTERED]"}])

D, [2022-09-23T06:40:49.537020 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.076217 0 retries] describe_subnets(subnet_ids:["subnet-09051861e82224071"])

D, [2022-09-23T06:40:49.781765 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.243969 0 retries] describe_security_groups(filters:[{name:"[FILTERED]",values:"[FILTERED]"}])

I, [2022-09-23T06:40:49.782599 #28350]  INFO -- [req_id cpi-787684]: Creating new instance with: {"image_id"=>"ami-0a32db245df5057c9", "instance_type"=>"t3.large", "key_name"=>"cf-stg", "user_data"=>"<redacted>", "block_device_mappings"=>[{"device_name"=>"/dev/sdb", "ebs"=>{"volume_size"=>49, "volume_type"=>"gp2", "delete_on_termination"=>true, "encrypted"=>true, "kms_key_id"=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}}, {"device_name"=>"/dev/xvda", "ebs"=>{"volume_type"=>"gp2", "delete_on_termination"=>true}}], "tag_specifications"=>[{"resource_type"=>"instance", "tags"=>[{"key"=>"GBL_CLASS_0", "value"=>"OPERATION"}, {"key"=>"GBL_CLASS_1", "value"=>"TEST"}, {"key"=>"SEC_ASSETS", "value"=>"scf"}]}], "placement"=>{"availability_zone"=>"ap-northeast-1a"}, "network_interfaces"=>[{"groups"=>["sg-06c341a31813f550c", "sg-023b0c80cc3bdb331"], "subnet_id"=>"subnet-09051861e82224071", "device_index"=>0}]}
I, [2022-09-23T06:40:49.782669 #28350]  INFO -- [req_id cpi-787684]: Launching spot instance...
D, [2022-09-23T06:40:49.783092 #28350] DEBUG -- [req_id cpi-787684]: Requesting spot instance with: {"spot_price"=>"0.12", "instance_count"=>1, "launch_specification"=>{"image_id"=>"ami-0a32db245df5057c9", "instance_type"=>"t3.large", "key_name"=>"cf-stg", "user_data"=>"<redacted>", "block_device_mappings"=>[{"device_name"=>"/dev/sdb", "ebs"=>{"volume_size"=>49, "volume_type"=>"gp2", "delete_on_termination"=>true, "encrypted"=>true, "kms_key_id"=>"arn:aws:kms:ap-northeast-1:728983948160:key/7dd1ff2b-47a2-42b4-a25f-887fdb929030"}}, {"device_name"=>"/dev/xvda", "ebs"=>{"volume_type"=>"gp2", "delete_on_termination"=>true}}], "placement"=>{"availability_zone"=>"ap-northeast-1a"}, "network_interfaces"=>[{"groups"=>["sg-06c341a31813f550c", "sg-023b0c80cc3bdb331"], "subnet_id"=>"subnet-09051861e82224071", "device_index"=>0}]}}
D, [2022-09-23T06:40:50.629799 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.845635 0 retries] request_spot_instances(spot_price:"0.12",instance_count:1,launch_specification:{image_id:"ami-0a32db245df5057c9",instance_type:"t3.large",key_name:"cf-stg",user_data:#<String "eyJ2bSI6eyJuYW1lIjoidm0tYzZlZDVkNWMtNjM1MS00ZTBmLWExODQtMThm\nMjBlNDZkMjU1In0sImFnZW50X2lkIjoiZTZjZmMzNWMtNWYwNy00M2JmLTg2\nOTQtYmY1ZGY3YjZlYzkwIiwibmV0d29ya3MiOnsiZW5kcG9pbnRsZXNzIjp7\nInR5cGUiOiJkeW5hbWljIiwiY2xvdWRfcHJvcGVydGllcyI6eyJzZWN1cml0\neV9ncm91cHMiOlsiY2Ytc3RnLWJvc2giLCJjZi1zdGctcGFja2FnZXMiXSwi\nc3VibmV0Ijoic3VibmV0LTA5MDUxODYxZTgyMjI0MDcxIn0sImRlZmF1bHQi\nOlsiZG5zIiwiZ2F0ZXdheSJdLCJpcCI6IjEwLjEyMi4xMDMuMTkiLCJuZXRt\nYXNrIjoiMjU1LjI1NS4yNTUuMCIsImdhdGV3YXkiOiIxMC4xMjIuMTAzLjEi\nLCJ1c2VfZGhjcCI6dHJ1ZX19LCJkaXNrcyI6eyJzeXN0ZW0iOiIvZGV2L3h2\nZGEiLCJwZXJzaXN0ZW50Ijp7fSwiZXBoZW1lcmFsIjoiL2Rldi9zZGIifSwi\nZW52Ijp7ImJvc2giOnsiYmxvYnN0b3JlcyI6W3sib3B0aW9ucyI6eyJhY2Nl\nc3Nfa2V5X2lkIjoiQUtJQTJUT1dVSk9BT1RUVlZDTDIiLCJidWNrZXRfbmFt\nZSI6ImNmLXN0Zy1ibG9ic3RvcmUtYm9zaCIsInJlZ2lvbiI6ImFwLW5vcnRo\nZWFzdC0xIiwic2VjcmV0X2FjY2Vzc19rZXkiOiJWajdVRmpJZjRMZnBIT1RB\naUY1V3VrZ1l5TTJnNk01MTdtdThZdDlYIn0sInByb3ZpZGVyIjoiczMifV0s\nIm50cCI6WyIxNjkuMjU0LjE2OS4xMjMiLCJ0aW1lMS5nb29nbGUuY29tIiwi\ndGltZTIuZ29vZ2xlLmNvbSIs" ... (9267 bytes)>,block_device_mappings:[{device_name:"/dev/sdb",ebs:{volume_size:49,volume_type:"gp2",delete_on_termination:true,encrypted:true,kms_key_id:"[FILTERED]"}},{device_name:"/dev/xvda",ebs:{volume_type:"gp2",delete_on_termination:true}}],placement:{availability_zone:"ap-northeast-1a"},network_interfaces:[{groups:["sg-06c341a31813f550c","sg-023b0c80cc3bdb331"],subnet_id:"subnet-09051861e82224071",device_index:0}]})

D, [2022-09-23T06:40:50.630084 #28350] DEBUG -- [req_id cpi-787684]: Got spot instance requests: #<struct Aws::EC2::Types::RequestSpotInstancesResult spot_instance_requests=[#<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:50 UTC, fault=nil, instance_id=nil, launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="default", group_id=nil>], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=49, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.large", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-09051861e82224071">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone=nil, product_description="Linux/UNIX", spot_instance_request_id="sir-n266fexh", spot_price="0.120000", state="open", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="pending-evaluation", message="Your Spot request has been submitted for review, and is pending evaluation.", update_time=2022-09-23 06:40:50 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=nil, instance_interruption_behavior="terminate">]>
D, [2022-09-23T06:40:50.630196 #28350] DEBUG -- [req_id cpi-787684]: Checking state of spot instance requests...
D, [2022-09-23T06:40:50.667347 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 400 0.036653 0 retries] describe_spot_instance_requests(spot_instance_request_ids:["sir-n266fexh"]) Aws::EC2::Errors::InvalidSpotInstanceRequestIDNotFound The spot instance request ID 'sir-n266fexh' does not exist

W, [2022-09-23T06:41:20.673761 #28350]  WARN -- [req_id cpi-787684]: Retrying after expected error: The spot instance request ID 'sir-n266fexh' does not exist
D, [2022-09-23T06:41:20.673850 #28350] DEBUG -- [req_id cpi-787684]: Checking state of spot instance requests...
D, [2022-09-23T06:41:20.826860 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.152434 0 retries] describe_spot_instance_requests(spot_instance_request_ids:["sir-n266fexh"])

D, [2022-09-23T06:41:20.827214 #28350] DEBUG -- [req_id cpi-787684]: Spot instance request status: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:50 UTC, fault=nil, instance_id="i-0e12405083d002899", launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh", group_id="sg-06c341a31813f550c">, #<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-packages", group_id="sg-023b0c80cc3bdb331">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=49, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.large", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-09051861e82224071">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-n266fexh", spot_price="0.120000", state="active", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="fulfilled", message="Your spot request is fulfilled.", update_time=2022-09-23 06:40:54 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:50 UTC, instance_interruption_behavior="terminate">
I, [2022-09-23T06:41:20.827419 #28350]  INFO -- [req_id cpi-787684]: Spot request instances fulfilled: #<struct Aws::EC2::Types::SpotInstanceRequest actual_block_hourly_price=nil, availability_zone_group=nil, block_duration_minutes=nil, create_time=2022-09-23 06:40:50 UTC, fault=nil, instance_id="i-0e12405083d002899", launch_group=nil, launch_specification=#<struct Aws::EC2::Types::LaunchSpecification user_data=nil, security_groups=[#<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-bosh", group_id="sg-06c341a31813f550c">, #<struct Aws::EC2::Types::GroupIdentifier group_name="cf-stg-packages", group_id="sg-023b0c80cc3bdb331">], addressing_type=nil, block_device_mappings=[#<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/sdb", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=true, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=49, volume_type="gp2">, no_device=nil>, #<struct Aws::EC2::Types::BlockDeviceMapping device_name="/dev/xvda", virtual_name=nil, ebs=#<struct Aws::EC2::Types::EbsBlockDevice encrypted=nil, delete_on_termination=true, iops=nil, kms_key_id=nil, snapshot_id=nil, volume_size=nil, volume_type="gp2">, no_device=nil>], ebs_optimized=nil, iam_instance_profile=nil, image_id="ami-0a32db245df5057c9", instance_type="t3.large", kernel_id=nil, key_name="cf-stg", network_interfaces=[#<struct Aws::EC2::Types::InstanceNetworkInterfaceSpecification associate_public_ip_address=nil, delete_on_termination=nil, description=nil, device_index=0, groups=[], ipv_6_address_count=nil, ipv_6_addresses=[], network_interface_id=nil, private_ip_address=nil, private_ip_addresses=[], secondary_private_ip_address_count=nil, subnet_id="subnet-09051861e82224071">], placement=#<struct Aws::EC2::Types::SpotPlacement availability_zone="ap-northeast-1a", group_name=nil, tenancy=nil>, ramdisk_id=nil, subnet_id=nil, monitoring=#<struct Aws::EC2::Types::RunInstancesMonitoringEnabled enabled=false>>, launched_availability_zone="ap-northeast-1a", product_description="Linux/UNIX", spot_instance_request_id="sir-n266fexh", spot_price="0.120000", state="active", status=#<struct Aws::EC2::Types::SpotInstanceStatus code="fulfilled", message="Your spot request is fulfilled.", update_time=2022-09-23 06:40:54 UTC>, tags=[], type="one-time", valid_from=nil, valid_until=2022-09-30 06:40:50 UTC, instance_interruption_behavior="terminate">
I, [2022-09-23T06:41:20.827589 #28350]  INFO -- [req_id cpi-787684]: attempting to tag object: i-0e12405083d002899
D, [2022-09-23T06:41:20.950783 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.122494 0 retries] create_tags(tags:[{key:"GBL_CLASS_0",value:"[FILTERED]"},{key:"GBL_CLASS_1",value:"[FILTERED]"},{key:"SEC_ASSETS",value:"[FILTERED]"}],resources:["i-0e12405083d002899"])

I, [2022-09-23T06:41:20.950970 #28350]  INFO -- [req_id cpi-787684]: Waiting for instance to exist...
D, [2022-09-23T06:41:21.021635 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.070034 0 retries] describe_instances(instance_ids:["i-0e12405083d002899"])

I, [2022-09-23T06:41:21.022048 #28350]  INFO -- [req_id cpi-787684]: Waiting for instance to be ready...
D, [2022-09-23T06:41:21.076597 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.053971 0 retries] describe_instances(instance_ids:["i-0e12405083d002899"])

W, [2022-09-23T06:41:21.077405 #28350]  WARN -- [req_id cpi-787684]: Failed to configure instance 'i-0e12405083d002899': #<Aws::Waiters::Errors::FailureStateError: stopped waiting, encountered a failure state>
D, [2022-09-23T06:41:21.304004 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.226086 0 retries] terminate_instances(instance_ids:["i-0e12405083d002899"])

I, [2022-09-23T06:41:21.304119 #28350]  INFO -- [req_id cpi-787684]: Deleting instance settings for 'i-0e12405083d002899'
I, [2022-09-23T06:41:21.304159 #28350]  INFO -- [req_id cpi-787684]: Deleting instance 'i-0e12405083d002899'
D, [2022-09-23T06:41:21.363949 #28350] DEBUG -- [req_id cpi-787684]: [Aws::EC2::Client 200 0.059213 0 retries] describe_instances(instance_ids:["i-0e12405083d002899"])

E, [2022-09-23T06:41:21.364468 #28350] ERROR -- [req_id cpi-787684]: Failed to create instance: stopped waiting, encountered a failure state
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:111:in `block in poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `loop'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:102:in `poll'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:92:in `block (2 levels) in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:91:in `block in wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `catch'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-core-3.22.0/lib/aws-sdk-core/waiters/waiter.rb:90:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/waiters.rb:484:in `wait'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/aws-sdk-ec2-1.36.0/lib/aws-sdk-ec2/instance.rb:369:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance.rb:65:in `wait_until_running'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:69:in `babysit_instance_creation'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/instance_manager.rb:42:in `create'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_core.rb:89:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:64:in `block in create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_common-1.3262.24.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/lib/cloud/aws/cloud_v2.rb:51:in `create_vm'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `public_send'
/var/vcap/data/packages/bosh_aws_cpi/7c7e65f121154d9a6427ac92b4c4ebae61984f85/vendor/bundle/ruby/2.6.0/gems/bosh_cpi-2.5.0/lib/bosh/cpi/cli.rb:89:in `run'
/var/vcap/packages/bosh_aws_cpi/bin/aws_cpi:28:in `<top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:63:in `kernel_load'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli/exec.rb:28:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:476:in `exec'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor.rb:399:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:30:in `dispatch'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/vendor/thor/lib/thor/base.rb:476:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/cli.rb:24:in `start'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:46:in `block in <top (required)>'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/site_ruby/2.6.0/bundler/friendly_errors.rb:123:in `with_friendly_errors'
/var/vcap/data/packages/ruby-2.6.5-r0.29.0/07e7c7bab898949d567ad0d9d3903f3fd135d907/lib/ruby/gems/2.6.0/gems/bundler-2.1.2/exe/bundle:34:in `<top (required)>'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `load'
/var/vcap/packages/ruby-2.6.5-r0.29.0/bin/bundle:23:in `<main>'
I, [2022-09-23T06:41:21.364710 #28350]  INFO -- [req_id cpi-787684]: Finished create_vm in 32.17 seconds

Task 319812 error

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

Exit code 1

I am testing the application of the aws ebs encrypt option. Apply the ebs encrypt option to bosh and redeploy After that, when I recreate the concourse deployment, I get this error.

beyhan commented 2 years ago

Could you check in the AWS Console the state of the instance which BOSH failed to create? Is it possible to ssh into that instance and check for logs, e.g. the agent logs under /var/vcap/bosh/current?

kwonsoonwoo commented 2 years ago

@beyhan Failed instances in the AWS Console are terminated and are not listed. So I can't see the log by connecting to the instance with bosh ssh.

The log in the bosh director looks like this:

2022-09-26_02:05:38.37317 [monitJobSupervisor] 2022/09/26 02:05:38 DEBUG - Getting monit status
2022-09-26_02:05:38.37319 [http-client] 2022/09/26 02:05:38 DEBUG - status function called
2022-09-26_02:05:38.37320 [http-client] 2022/09/26 02:05:38 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:05:38.37320 [attemptRetryStrategy] 2022/09/26 02:05:38 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:05:38.37495 ********************
2022-09-26_02:05:38.37501 [File System] 2022/09/26 02:05:38 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:05:38.37501 [File System] 2022/09/26 02:05:38 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:05:38.37506 [File System] 2022/09/26 02:05:38 DEBUG - Write content
2022-09-26_02:05:38.37507 ********************
2022-09-26_02:05:38.37507 {"state":"running"}
2022-09-26_02:05:38.37507 ********************
2022-09-26_02:06:08.37312 [monitJobSupervisor] 2022/09/26 02:06:08 DEBUG - Getting monit status
2022-09-26_02:06:08.37314 [http-client] 2022/09/26 02:06:08 DEBUG - status function called
2022-09-26_02:06:08.37315 [http-client] 2022/09/26 02:06:08 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:06:08.37315 [attemptRetryStrategy] 2022/09/26 02:06:08 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:06:08.37478 ********************
2022-09-26_02:06:08.37482 [File System] 2022/09/26 02:06:08 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:06:08.37482 [File System] 2022/09/26 02:06:08 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:06:08.37487 [File System] 2022/09/26 02:06:08 DEBUG - Write content
2022-09-26_02:06:08.37489 ********************
2022-09-26_02:06:08.37489 {"state":"running"}
2022-09-26_02:06:08.37489 ********************
2022-09-26_02:06:38.37313 [monitJobSupervisor] 2022/09/26 02:06:38 DEBUG - Getting monit status
2022-09-26_02:06:38.37315 [http-client] 2022/09/26 02:06:38 DEBUG - status function called
2022-09-26_02:06:38.37315 [http-client] 2022/09/26 02:06:38 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:06:38.37315 [attemptRetryStrategy] 2022/09/26 02:06:38 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:06:38.37486 ********************
2022-09-26_02:06:38.37496 [File System] 2022/09/26 02:06:38 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:06:38.37496 [File System] 2022/09/26 02:06:38 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:06:38.37496 [File System] 2022/09/26 02:06:38 DEBUG - Write content
2022-09-26_02:06:38.37497 ********************
2022-09-26_02:06:38.37497 {"state":"running"}
2022-09-26_02:06:38.37497 ********************
2022-09-26_02:07:08.37314 [monitJobSupervisor] 2022/09/26 02:07:08 DEBUG - Getting monit status
2022-09-26_02:07:08.37315 [http-client] 2022/09/26 02:07:08 DEBUG - status function called
2022-09-26_02:07:08.37316 [http-client] 2022/09/26 02:07:08 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:07:08.37316 [attemptRetryStrategy] 2022/09/26 02:07:08 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:07:08.37480 ********************
2022-09-26_02:07:08.37487 [File System] 2022/09/26 02:07:08 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:07:08.37488 [File System] 2022/09/26 02:07:08 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:07:08.37493 [File System] 2022/09/26 02:07:08 DEBUG - Write content
2022-09-26_02:07:08.37493 ********************
2022-09-26_02:07:08.37493 {"state":"running"}
2022-09-26_02:07:08.37493 ********************
2022-09-26_02:07:38.37317 [monitJobSupervisor] 2022/09/26 02:07:38 DEBUG - Getting monit status
2022-09-26_02:07:38.37319 [http-client] 2022/09/26 02:07:38 DEBUG - status function called
2022-09-26_02:07:38.37320 [http-client] 2022/09/26 02:07:38 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:07:38.37320 [attemptRetryStrategy] 2022/09/26 02:07:38 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:07:38.37476 ********************
2022-09-26_02:07:38.37493 [File System] 2022/09/26 02:07:38 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:07:38.37494 [File System] 2022/09/26 02:07:38 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:07:38.37494 [File System] 2022/09/26 02:07:38 DEBUG - Write content
2022-09-26_02:07:38.37494 ********************
2022-09-26_02:07:38.37495 {"state":"running"}
2022-09-26_02:07:38.37495 ********************
2022-09-26_02:08:08.37313 [monitJobSupervisor] 2022/09/26 02:08:08 DEBUG - Getting monit status
2022-09-26_02:08:08.37315 [http-client] 2022/09/26 02:08:08 DEBUG - status function called
2022-09-26_02:08:08.37315 [http-client] 2022/09/26 02:08:08 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:08:08.37317 [attemptRetryStrategy] 2022/09/26 02:08:08 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:08:08.37484 ********************
2022-09-26_02:08:08.37488 [File System] 2022/09/26 02:08:08 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:08:08.37488 [File System] 2022/09/26 02:08:08 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:08:08.37493 [File System] 2022/09/26 02:08:08 DEBUG - Write content
2022-09-26_02:08:08.37493 ********************
2022-09-26_02:08:08.37493 {"state":"running"}
2022-09-26_02:08:08.37493 ********************
2022-09-26_02:08:38.37314 [monitJobSupervisor] 2022/09/26 02:08:38 DEBUG - Getting monit status
2022-09-26_02:08:38.37318 [http-client] 2022/09/26 02:08:38 DEBUG - status function called
2022-09-26_02:08:38.37319 [http-client] 2022/09/26 02:08:38 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:08:38.37319 [attemptRetryStrategy] 2022/09/26 02:08:38 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:08:38.37478 ********************
2022-09-26_02:08:38.37493 [File System] 2022/09/26 02:08:38 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:08:38.37493 [File System] 2022/09/26 02:08:38 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:08:38.37493 [File System] 2022/09/26 02:08:38 DEBUG - Write content
2022-09-26_02:08:38.37494 ********************
2022-09-26_02:08:38.37494 {"state":"running"}
2022-09-26_02:08:38.37495 ********************
2022-09-26_02:09:08.37314 [monitJobSupervisor] 2022/09/26 02:09:08 DEBUG - Getting monit status
2022-09-26_02:09:08.37316 [http-client] 2022/09/26 02:09:08 DEBUG - status function called
2022-09-26_02:09:08.37316 [http-client] 2022/09/26 02:09:08 DEBUG - Monit request: url='http://127.0.0.1:2822/_status2?format=xml' body=''
2022-09-26_02:09:08.37316 [attemptRetryStrategy] 2022/09/26 02:09:08 DEBUG - Making attempt #0 for *httpclient.RequestRetryable
2022-09-26_02:09:08.37317 [clientRetryable] 2022/09/26 02:09:08 DEBUG - [requestID=dea4a877-612e-4544-5468-f8e437896a7b] Requesting (attempt=1): Request{ Method: 'GET', URL: 'http://127.0.0.1:2822/_status2?format=xml' }
2022-09-26_02:09:08.37442 [File System] 2022/09/26 02:09:08 DEBUG - Checking if file exists /var/vcap/monit/stopped
2022-09-26_02:09:08.37443 [File System] 2022/09/26 02:09:08 DEBUG - Stat '/var/vcap/monit/stopped'
2022-09-26_02:09:08.37443 [agent] 2022/09/26 02:09:08 DEBUG - Building heartbeat
2022-09-26_02:09:08.37453 [File System] 2022/09/26 02:09:08 DEBUG - Checking if file exists /var/vcap/bosh/spec.json
2022-09-26_02:09:08.37454 [File System] 2022/09/26 02:09:08 DEBUG - Stat '/var/vcap/bosh/spec.json'
2022-09-26_02:09:08.37455 [File System] 2022/09/26 02:09:08 DEBUG - Reading file /var/vcap/bosh/spec.json
2022-09-26_02:09:08.37465 [File System] 2022/09/26 02:09:08 DEBUG - Read content
2022-09-26_02:09:08.37465 ********************
2022-09-26_02:09:08.37465 {"properties":{"logging":{"max_log_file_size":""}},"job":{"name":"bosh","release":"","template":"","version":"","templates":[{"name":"bpm","version":"f18421d8c21c425e94bdb3b2df00f3eca2daef29"},{"name":"nats","version":"4d19655090e879ab051dbe10ad350d9d736bae7762e1bd0b31333d8a5f9abbdd"},{"name":"director","version":"686d39a5ee6a7b928dd0cdc77cd13d2ffbdf683317bd30fb598df29f9bd3ac91"},{"name":"health_monitor","version":"dfdd6de6315928296e7cd9eed8400fedeb98b72c14573575bf1e243e0eada1a3"},{"name":"registry","version":"46af0f7ba2a3850b2b5ae7c572ad37d91bd9898b6a73180fcd048fd3944cfad2"},{"name":"aws_cpi","version":"5c543b15f01b77eeebd4bf9be21ff6d04903b4e4505dcb129d6cd170ca1b649f"},{"name":"uaa","version":"4d087031dd8302804dd192e8168230a376a187d04a6e255f597c9540f8a41266"},{"name":"bbr-uaadb","version":"b10586c070c07129cd8f62188cd4754c403fb163812607dce31985e8e61781f0"},{"name":"credhub","version":"e6962d08ba560f3e58b2cd106d6deaf86268f4df"},{"name":"bbr-credhubdb","version":"864e25ff3eddedfbba6b722d9ecfd03d488ea7e9"}]},"packages":{"bosh-gcscli":{"name":"bosh-gcscli","version":"52223432539bbd0607db053f542440869688b4404dd65f2ddf33c2d195b1b891","sha1":"e6a2870ecc2d3952a616afcbb148628d2db6bd9d","blobstore_id":"af140bc6-ca74-4d6a-5eb4-2a06eae0df90","signed_url":""},"bosh_aws_cpi":{"name":"bosh_aws_cpi","version":"e1613e26ab5ea97915f1d6110905d3b17a9218a2f7187c74ff20fdeb44288c9d","sha1":"a11d3b900e23052058e3e8391d55d410c70b42be","blobstore_id":"1766e97e-89d1-48a3-7c65-cfb996fc6574","signed_url":""},"bpm":{"name":"bpm","version":"818bd9ec39fa5e179c5406c1690fb7c6deb0fc4d","sha1":"03d07ff41afd8944c836142ed441d1f6a3536e78","blobstore_id":"fc83bd9b-993f-43d9-5abb-a38683b45041","signed_url":""},"bpm-runc":{"name":"bpm-runc","version":"3dcaebacd63b8adc75c5f32954f11041885347b1","sha1":"599336ccc0fa5539e7b5fde7eb6f73856e2c6245","blobstore_id":"957b7c49-03a2-4d66-78ec-bf6aac2db41f","signed_url":""},"credhub":{"name":"credhub","version":"aa7291a27ef93cd64d80033b58512391c753523e","sha1":"c007f7b699fa93b33c52a1da302a6df05ea99a08","blobstore_id":"eec82b9e-4fe0-48b0-74e4-fd01c9138d10","signed_url":""},"davcli":{"name":"davcli","version":"58f558960854f58c55e3d506d3906019178dbc189fbbed1616b8b3c7c02142ea","sha1":"e18469ff77790980319fb25c61574f2e5f873137","blobstore_id":"7920e1a8-3835-44f6-6de7-66ad60395ca8","signed_url":""},"director":{"name":"director","version":"f32385256198535b797059dd4990fcb3b65c0c07337990163c24275a7a29b7e1","sha1":"2d2229cddd045404722284addac29f475aee8e47","blobstore_id":"8509cb76-11e0-48cd-5981-9d2439ea2909","signed_url":""},"golang":{"name":"golang","version":"7b633f7a140b41ef9427109d0f3032cf81445ead","sha1":"43f0161096274a973db7fc9e270d7fd2ebc96234","blobstore_id":"06157c0c-7a8d-4fcc-6097-95b62a0d8d5b","signed_url":""},"gonats":{"name":"gonats","version":"f58980bd4b0436ff65f588627116dfff63f346f4d13175b7ba47380ab89e08a6","sha1":"17189364088b0bf614a1c06feffb49ca05af82a9","blobstore_id":"b17056e9-6c77-4fe2-785d-c1b9333d5b8b","signed_url":""},"health_monitor":{"name":"health_monitor","version":"dd842698e83edeae08bdcc6e672429a5cee3b755645d2024d97b6213f1281d44","sha1":"0ae6d3a9ccce5b349eeef4b9bcf29a1f7b4b184f","blobstore_id":"5821a130-fe09-4bbe-4fc6-d61ae168f5bf","signed_url":""},"libpq":{"name":"libpq","version":"ecbfa62322b4124f25372a19d68b83295b4d290503153667ec378e3196c45f69","sha1":"a4876199c81047aad2296cbd992a8fe0b59ad783","blobstore_id":"f281da6d-acc0-402c-6b90-8af5a07f89e7","signed_url":""},"luna-hsm-client-7.4":{"name":"luna-hsm-client-7.4","version":"746f3c30aadc0af7afc2d5cddcc16d8836a8f845","sha1":"5d05eceee1785ada8de9e57e4b5b042755d10cd4","blobstore_id":"7341ffa4-7e22-4ef7-5495-0c79a9131f6b","signed_url":""},"mysql":{"name":"mysql","version":"788d06685e1ea1d316759eeeb506782ec7f9302f8c21e2ff04cd4703579f0935","sha1":"6d4bb0ec1c8640210a6f0871d308f3670e6d328b","blobstore_id":"ad0c4af9-cae5-431f-40f4-2513965ae2aa","signed_url":""},"nginx":{"name":"nginx","version":"d4cf69d3e81bed005ebba5bc0bc8d2c28252e70ad47ff455479a9838d5f9b0e4","sha1":"638bda70829d8db97a1cd7d1716b9c7854803768","blobstore_id":"6b64cf57-da08-498b-4620-111d8af3053e","signed_url":""},"openjdk_1.8.0":{"name":"openjdk_1.8.0","version":"225f67373c9ad0a1da464aeb92f06207bd3e8da1","sha1":"b7822e1ac4fc6ff4cad3bad04cbe9216161ea1d1","blobstore_id":"46e51a7c-b5ff-46bf-7f89-85e61d4f99ea","signed_url":""},"postgres-9.4":{"name":"postgres-9.4","version":"601f3635b43d0e7ba3ae866e3bd69425cdf33f7fb34a7f1bb21cc26818fb598e","sha1":"19324ce507710577002ce0e562918f29637f48b5","blobstore_id":"b03a331d-e475-4dc8-5877-0d95c3515904","signed_url":""},"registry":{"name":"registry","version":"6867463b7f7d9afd579b482bf53ebd54c64c2ad773a92b21e1b4904504d81b10","sha1":"8b5e982ba43412ab5b4d52fa61142636a79e1091","blobstore_id":"8d0e2cdb-b7ee-411d-57e4-51ab995ca1bb","signed_url":""},"ruby-2.6.5-r0.29.0":{"name":"ruby-2.6.5-r0.29.0","version":"269dc54d5306119b0e4f89be04f6c470b4876f552753815586fd1ab8ebeaa70d","sha1":"0c7b30c78e6b3191bd86ea48025c97a8f5b724c5","blobstore_id":"d9a11828-3e0e-40ad-5ea6-c0c420870b6c","signed_url":""},"s3cli":{"name":"s3cli","version":"7e752dee192da026f6a0cdf2653b855cc6efbe6b041564660f8520c39ddd5a78","sha1":"4f728e25770e2472f2d81e84de3357a07c51b75c","blobstore_id":"ff21efa2-9a48-484f-7267-c39b5a0e8e25","signed_url":""},"tini":{"name":"tini","version":"3d7b02f3eeb480b9581bec4a0096dab9ebdfa4bc","sha1":"251ac5421512789dabfb49fcf9fadff892935aa0","blobstore_id":"1194d211-3f8f-457c-5d63-e591ba63f5c0","signed_url":""},"uaa":{"name":"uaa","version":"05709bb8efc72b43a95a17a112ac0ca42729370fe182dc0fb8e135696e131ebe","sha1":"bd0c6baf22384caaac134dec6aa3968f56329212","blobstore_id":"9b9f469a-f6ec-4669-659e-d097d81415d6","signed_url":""},"verify_multidigest":{"name":"verify_multidigest","version":"64d1958934e10a0eccc05ddf0d7ba0c8215e6f6d4c227cb93998087335378fa8","sha1":"3689ea49668cc835bb849c61ab9590e2b7715201","blobstore_id":"db23b1f8-c4a6-457a-7e78-95b115f672ac","signed_url":""}},"configuration_hash":"unused-configuration-hash","networks":{"default":{"cloud_properties":{"subnet":"subnet-0b1ea5a9d314e553f"},"default":["dns","gateway"],"dns":["8.8.8.8"],"gateway":"10.122.100.1","ip":"10.122.100.6","netmask":"255.255.255.0","type":"manual"}},"resource_pool":null,"deployment":"bosh","name":"bosh","index":0,"id":"0","az":"unknown","persistent_disk":0,"rendered_templates_archive":{"sha1":"sha256:37d03ab4093068bdeae9430056f2306cf7adc904ed5efff08be7eea74cc0a424","blobstore_id":"6dd2889a-861e-4eac-5796-422af27c0bcc","signed_url":""}}
2022-09-26_02:09:08.37475 ********************
2022-09-26_02:09:08.37485 [File System] 2022/09/26 02:09:08 DEBUG - Writing /var/vcap/instance/health.json
2022-09-26_02:09:08.37486 [File System] 2022/09/26 02:09:08 DEBUG - Making dir /var/vcap/instance with perm 0777
2022-09-26_02:09:08.37487 [File System] 2022/09/26 02:09:08 DEBUG - Write content
2022-09-26_02:09:08.37487 ********************
2022-09-26_02:09:08.37487 {"state":"running"}
2022-09-26_02:09:08.37487 ********************

I am trying to redeploy by applying the aws ebs encrypt option to bosh. An error occurs in logsearch, concourse.

Do you have any information on whether recreate works well from what version of the bosh director or higher?

beyhan commented 2 years ago

You could use the option keep_unreachable_vms to keep the VM for debugging.

I'm not aware of any issues with recreated when switching to encrypted volumes.

kwonsoonwoo commented 2 years ago

I am using bosh director 271.2.0. I applied the keep_unreachable_vms option you mentioned and recreated it after redeploy, but the failed vm disappeared.

$ bosh env
Using environment '10.122.100.6' as client 'admin'

Name               cf-stg
UUID               8918c85c-4e34-4af1-a19f-3ad5498831a5
Version            271.2.0 (00000000)
Director Stemcell  ubuntu-xenial/621.93
CPI                aws_cpi
Features           compiled_package_cache: disabled
                   config_server: enabled
                   local_dns: enabled
                   power_dns: disabled
                   snapshots: enabled
User               admin

Succeeded

$ bosh -d logsearch recreate --fix
Using environment '10.122.100.6' as client 'admin'

Using deployment 'logsearch'

Continue? [yN]: y

Task 328816

Task 328816 | 06:53:12 | Preparing deployment: Preparing deployment (00:00:02)
Task 328816 | 06:53:14 | Preparing deployment: Rendering templates (00:00:07)
Task 328816 | 06:53:22 | Preparing package compilation: Finding packages to compile (00:00:00)
Task 328816 | 06:53:22 | Creating missing vms: cluster_monitor/b8f3f050-d6ee-493c-ad95-7e84fb7d8457 (0)
Task 328816 | 06:53:22 | Creating missing vms: elasticsearch_data/9062743c-8b91-40ae-8978-af979e1d03ea (0)
Task 328816 | 06:53:22 | Creating missing vms: elasticsearch_data/792a6635-f3c3-4f76-9e3b-9f79919b2c09 (2)
Task 328816 | 06:53:22 | Creating missing vms: ingestor/9c91a9d1-6913-4be7-be41-30679700042d (0)
Task 328816 | 06:53:59 | Creating missing vms: cluster_monitor/b8f3f050-d6ee-493c-ad95-7e84fb7d8457 (0) (00:00:37)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-862439')
Task 328816 | 06:54:00 | Creating missing vms: ingestor/9c91a9d1-6913-4be7-be41-30679700042d (0) (00:00:38)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-908272')
Task 328816 | 06:54:30 | Creating missing vms: elasticsearch_data/9062743c-8b91-40ae-8978-af979e1d03ea (0) (00:01:08)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-911057')
Task 328816 | 06:54:45 | Creating missing vms: elasticsearch_data/792a6635-f3c3-4f76-9e3b-9f79919b2c09 (2) (00:01:23)
                      L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-762756')
Task 328816 | 06:54:45 | Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-862439')

Task 328816 Started  Tue Sep 27 06:53:12 UTC 2022
Task 328816 Finished Tue Sep 27 06:54:45 UTC 2022
Task 328816 Duration 00:01:33
Task 328816 error

Changing state:
  Expected task '328816' to succeed but state is 'error'

Exit code 1
$ bosh vms -d logsearch
Using environment '10.122.100.6' as client 'admin'

Task 328820. Done

Deployment 'logsearch'

Instance                                                   Process State  AZ  IPs             VM CID               VM Type                Active
elasticsearch_data/819d3b1d-8c50-4815-af1c-a13e8a313b00    running        z2  10.122.102.126  i-0cbddd1b934eb96b5  medium-highmem-r_spot  true
elasticsearch_master/0abd24cb-7db9-4aad-b5f9-d4d0fab47c7a  running        z1  10.122.100.34   i-04f0c78aceb0dd6cd  medium                 true
elasticsearch_master/3209645b-f628-4f7a-88df-da39d0fac380  running        z1  10.122.100.160  i-090cfb4e6ec3c7345  medium                 true
elasticsearch_master/cc4088a9-62d6-49dc-9b78-d62b2e88c016  running        z2  10.122.102.166  i-00a2338acd56d2e92  medium                 true
ingestor/cd641ffe-dcda-43cc-a19c-8d753a7a55b3              running        z2  10.122.102.105  i-02ac39e529410d76a  medium-highmem-r_spot  true
kibana/351f99fb-1d42-45a8-8557-161030ff93ee                running        z1  10.122.100.121  i-0472c0b19383eb21d  large_spot             true
ls-router/8da3ad1f-7e47-464a-a37d-38cda9d46865             running        z1  10.122.100.192  i-01cb77509224ec727  medium                 true
maintenance/32e37de9-238a-4479-a2e9-3246bdb4daa7           running        z1  10.122.100.103  i-0d9b4a8aabe7f22b6  medium                 true

8 vms

Succeeded

I applied the option like this, is that correct?

cloud_provider:
  cert: ((mbus_bootstrap_ssl))
  mbus: https://mbus:((mbus_bootstrap_password))@((internal_ip)):6868
  properties:
    agent:
      mbus: https://mbus:((mbus_bootstrap_password))@0.0.0.0:6868
    blobstore:
      path: /var/vcap/micro_bosh/data/cache
      provider: local
disk_pools:
- disk_size: 65536
  name: disks
instance_groups:
- instances: 1
  jobs:
  - name: bpm
    release: bpm
  - name: nats
    release: bosh
  - name: postgres-10
    release: bosh
  - name: blobstore
    release: bosh
  - name: director
    release: bosh
  - name: health_monitor
    release: bosh
  name: bosh
  networks:
  - name: default
    static_ips:
    - ((internal_ip))
  persistent_disk_pool: disks
  properties:
    agent:
      env:
        bosh:
          blobstores:
          - options:
              endpoint: https://((internal_ip)):25250
              password: ((blobstore_agent_password))
              tls:
                cert:
                  ca: ((blobstore_ca.certificate))
              user: agent
            provider: dav
          ntp:
          - time1.google.com
          - time2.google.com
          - time3.google.com
          - time4.google.com
      mbus: nats://nats:((nats_password))@((internal_ip)):4222
    blobstore:
      address: ((internal_ip))
      agent:
        password: ((blobstore_agent_password))
        user: agent
        director:
        password: ((blobstore_director_password))
        user: director
      port: 25250
      provider: dav
      tls:
        cert:
          ca: ((blobstore_ca.certificate))
          certificate: ((blobstore_server_tls.certificate))
          private_key: ((blobstore_server_tls.private_key))
    director:
      address: 127.0.0.1
      db:
        adapter: postgres
        database: bosh
        host: 127.0.0.1
        listen_address: 127.0.0.1
        password: ((postgres_password))
        user: postgres
      enable_dedicated_status_worker: true
      enable_nats_delivered_templates: true
      enable_post_deploy: true
      events:
        record_events: true
      flush_arp: true
      generate_vm_passwords: true
      local_dns:
        enabled: true
      name: ((director_name))
      ssl:
        cert: ((director_ssl.certificate))
        key: ((director_ssl.private_key))
      user_management:
        local:
          users:
          - name: admin
            password: ((admin_password))
          - name: hm
            password: ((hm_password))
        provider: local
      workers: 4
      debug:
        keep_unreachable_vms: true <- added
beyhan commented 2 years ago

Hi, it looks like that the VM is preserved only if it was created successfully (check this). If the creation fails then this property doesn't have any effect (check this). Sorry, I wasn't aware of this detail.

Maybe you could try to manipulate the director code in to not delete the VM in case you have a test environment and try to debug it afterwards. Is this something you could try?

ramonskie commented 2 years ago

i'm not sure but could it maby that the machine type is not available anymore. aws changed and deprecated there machine types lately it also seems your using an older aws cpi as well as it is still using ruby 2.6.x

is this also only happening on this specific deployment? if so can you deploy/redeploy other deployments wihtout any issues. you also stated that your using ebs encryption have you tried to deploy without encryption? as some machine types cannot use ebs encryption see https://docs.aws.amazon.com/AWSEC2/latest/UserGuide/EBSEncryption.html#ebs-encryption-requirements

kwonsoonwoo commented 2 years ago

@ramonskie Current situation

I looked at the site you mentioned. However, the currently deployed instance type is t3 or r5, so it meets the ebs encrypt requirements in AWS.

kwonsoonwoo commented 2 years ago

@beyhan hi no need to be sorry

I can manipulate the director code, but I don't know the go language well. can you tell me what to do?

beyhan commented 2 years ago

It's not Golang but Ruby. Basically, you need to comment out this line https://github.com/cloudfoundry/bosh/blob/da56d19e30234239582ecfdd6a2da682631f6832/src/bosh-director/lib/bosh/director/deployment_plan/steps/create_vm_step.rb#L167

You can ssh into your BOSH Director find the location of create_vm_step.rb file. Comment out line and monit stop and monit start of your director process so that changes can take an effect. Just don't do this in productive environments.

When you are done with the debugging you should redeploy your BOSH Director to have a clean state again.

ramonskie commented 1 year ago

there has been no activity for more than 2 weeks. please reopen this issue if it still persists

kwonsoonwoo commented 1 year ago

@beyhan

$ monit restart all $ monit summary Tue Nov 8 05:55:23 2022

The Monit daemon 5.2.5 uptime: 23h 34m

Process 'nats' running Process 'director' running Process 'worker_1' running Process 'worker_2' running Process 'worker_3' running Process 'worker_4' running Process 'director_scheduler' running Process 'director_sync_dns' running Process 'director_nginx' running Process 'health_monitor' running Process 'registry' running Process 'cpi' running Process 'uaa' running Process 'credhub' running System 'system_localhost' running


- logsearch recreate
  - The instance in which the error occurred is deleted.

$ bosh vms -d logsearch Using environment '10.122.100.6' as client 'admin'

Task 414338. Done

Deployment 'logsearch'

Instance Process State AZ IPs VM CID VM Type Active elasticsearch_data/ac0a9910-cd4b-42b9-89ff-8793be912f36 running z1 10.122.100.44 i-002058eea7e2744d9 medium-highmem-r_spot true elasticsearch_data/f3ed9895-a7fe-4a7e-be5f-ac6f266d4d72 running z1 10.122.100.75 i-09d3a16a2a7a7e41e medium-highmem-r_spot true elasticsearch_master/9877f45a-7c1d-43a3-ad5b-2deb7755db98 running z2 10.122.102.13 i-084a5d39e84f66ed5 medium true elasticsearch_master/b4e37ecf-ef8a-46db-ac8a-db4be76775cc running z1 10.122.100.228 i-01c17989a80a70161 medium true elasticsearch_master/fa96107e-f106-4cf0-91a3-29a6acdb663d running z1 10.122.100.147 i-0d1a8b5e5a9b003c1 medium true kibana/9c2b70bd-007c-4e8a-b732-8a5b95902e94 running z1 10.122.100.148 i-0b3c78a21bc187040 large_spot true ls-router/7ae213e3-8654-4989-9b5c-b82f5aeb7ace running z1 10.122.100.203 i-03b94f9decd9f5ce1 medium true maintenance/6919d479-8887-478c-ab4f-e6689e0b7019 running z1 10.122.100.210 i-04ea1797147f84ef0 medium true

8 vms

Succeeded

$ bosh -d logsearch recreate --fix Using environment '10.122.100.6' as client 'admin'

Using deployment 'logsearch'

Continue? [yN]: y

Task 414352

Task 414352 | 06:00:02 | Preparing deployment: Preparing deployment (00:00:02) Task 414352 | 06:00:04 | Preparing deployment: Rendering templates (00:00:07) Task 414352 | 06:00:12 | Preparing package compilation: Finding packages to compile (00:00:01) Task 414352 | 06:00:13 | Creating missing vms: cluster_monitor/d9e5d8db-bc04-422f-9689-76ffd717f063 (0) Task 414352 | 06:00:13 | Creating missing vms: elasticsearch_data/2543b62e-662f-4150-b131-dca4b3d483d0 (1) Task 414352 | 06:00:13 | Creating missing vms: ingestor/bdb9abd9-a9b2-49ff-a440-037df979122b (1) Task 414352 | 06:00:13 | Creating missing vms: ingestor/2b83c6c6-d72c-41c7-b5a7-b9541b873119 (0) Task 414352 | 06:00:50 | Creating missing vms: cluster_monitor/d9e5d8db-bc04-422f-9689-76ffd717f063 (0) (00:00:37) L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-636029') Task 414352 | 06:00:50 | Creating missing vms: ingestor/bdb9abd9-a9b2-49ff-a440-037df979122b (1) (00:00:37) L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-777754') Task 414352 | 06:00:50 | Creating missing vms: elasticsearch_data/2543b62e-662f-4150-b131-dca4b3d483d0 (1) (00:00:37) L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-592302') Task 414352 | 06:01:05 | Creating missing vms: ingestor/2b83c6c6-d72c-41c7-b5a7-b9541b873119 (0) (00:00:52) L Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-516576') Task 414352 | 06:01:05 | Error: Unknown CPI error 'Unknown' with message 'stopped waiting, encountered a failure state' in 'create_vm' CPI method (CPI request ID: 'cpi-636029')

Task 414352 Started Tue Nov 8 06:00:02 UTC 2022 Task 414352 Finished Tue Nov 8 06:01:05 UTC 2022 Task 414352 Duration 00:01:03 Task 414352 error

Changing state: Expected task '414352' to succeed but state is 'error'

Exit code 1

$ bosh vms -d logsearch Using environment '10.122.100.6' as client 'admin'

Task 414360. Done

Deployment 'logsearch'

Instance Process State AZ IPs VM CID VM Type Active elasticsearch_data/ac0a9910-cd4b-42b9-89ff-8793be912f36 running z1 10.122.100.44 i-002058eea7e2744d9 medium-highmem-r_spot true elasticsearch_data/f3ed9895-a7fe-4a7e-be5f-ac6f266d4d72 running z1 10.122.100.75 i-09d3a16a2a7a7e41e medium-highmem-r_spot true elasticsearch_master/9877f45a-7c1d-43a3-ad5b-2deb7755db98 running z2 10.122.102.13 i-084a5d39e84f66ed5 medium true elasticsearch_master/b4e37ecf-ef8a-46db-ac8a-db4be76775cc running z1 10.122.100.228 i-01c17989a80a70161 medium true elasticsearch_master/fa96107e-f106-4cf0-91a3-29a6acdb663d running z1 10.122.100.147 i-0d1a8b5e5a9b003c1 medium true kibana/9c2b70bd-007c-4e8a-b732-8a5b95902e94 running z1 10.122.100.148 i-0b3c78a21bc187040 large_spot true ls-router/7ae213e3-8654-4989-9b5c-b82f5aeb7ace running z1 10.122.100.203 i-03b94f9decd9f5ce1 medium true maintenance/6919d479-8887-478c-ab4f-e6689e0b7019 running z1 10.122.100.210 i-04ea1797147f84ef0 medium true

8 vms

Succeeded



- The debugging content is about 3900 lines, so it is attached separately.

[debug.txt](https://github.com/cloudfoundry/bosh/files/9958465/debug.txt)
kwonsoonwoo commented 1 year ago

@ramonskie please re-open issue.

beyhan commented 1 year ago

It is defiantly AWS failing to start the instance because from the logs:

I, [2022-11-08T06:00:50.275697 #13125]  INFO -- [req_id cpi-636029]: Waiting for instance to exist...
D, [2022-11-08T06:00:50.360707 #13125] DEBUG -- [req_id cpi-636029]: [Aws::EC2::Client 200 0.084413 0 retries] describe_instances(instance_ids:["i-010f8f72f76bc2a1f"])  

I, [2022-11-08T06:00:50.361115 #13125]  INFO -- [req_id cpi-636029]: Waiting for instance to be ready...
D, [2022-11-08T06:00:50.418731 #13125] DEBUG -- [req_id cpi-636029]: [Aws::EC2::Client 200 0.05701 0 retries] describe_instances(instance_ids:["i-010f8f72f76bc2a1f"])  

W, [2022-11-08T06:00:50.419612 #13125]  WARN -- [req_id cpi-636029]: Failed to configure instance 'i-010f8f72f76bc2a1f': #<Aws::Waiters::Errors::FailureStateError: stopped waiting, encountered a failure state>
D, [2022-11-08T06:00:50.573888 #13125] DEBUG -- [req_id cpi-636029]: [Aws::EC2::Client 200 0.153755 0 retries] terminate_instances(instance_ids:["i-010f8f72f76bc2a1f"])  

I, [2022-11-08T06:00:50.574030 #13125]  INFO -- [req_id cpi-636029]: Deleting instance settings for 'i-010f8f72f76bc2a1f'
I, [2022-11-08T06:00:50.574074 #13125]  INFO -- [req_id cpi-636029]: Deleting instance 'i-010f8f72f76bc2a1f'
D, [2022-11-08T06:00:50.688390 #13125] DEBUG -- [req_id cpi-636029]: [Aws::EC2::Client 200 0.113742 0 retries] describe_instances(instance_ids:["i-010f8f72f76bc2a1f"])

It is basically executing this part of the CPI code. Unfortunately, there is also a termination implemented in the CPI code when the AWS instance doesn't get ready in bosh_aws_cpi/lib/cloud/aws/instance_manager.rb#L80 . If we want to go this path you will need to comment that line also so that you have the instance for debugging. I saw that you are using spot instances. The failure could be related to spot instances.

My warning: Just don't do this in productive environments. When you are done with the debugging you should redeploy your BOSH Director to have a clean state again.

kwonsoonwoo commented 1 year ago

@beyhan One of the problems you mentioned was caused by a spot instance. The VMs in question were spot instances, so I changed them to normal instances and it worked!

But I have another question.

Why isn't the storage all encrypted with ebs and only /dev/sdb is encrypted? (Like the picture below)

image

beyhan commented 1 year ago

It is a CPI configuration. E.g. in AWS CPI https://bosh.io/docs/aws-cpi/#global if you configure the encrypted global property all volumes are encrypted as documented in the link above.

kwonsoonwoo commented 1 year ago

@beyhan Thank you so much for your sincere answer.

https://bosh.io/docs/aws-cpi/#global Referring to the above, I looked at the yaml files of bosh-deployment. There was an encrypted-disk.yml file. (https://github.com/cloudfoundry/bosh-deployment/blob/master/aws/encrypted-disk.yml)

After comparing it with the documentation, it seemed that I could apply the yml file as it is. But the result is the same.

Could it be that I'm missing something?

beyhan commented 1 year ago

If you set the global property as in this will encrypt all newly created volumes. This property won't trigger encryption for existing volumes.