search

cloudfoundry / bosh-azure-cpi-release

BOSH Azure CPI
Apache License 2.0
63 stars 88 forks source link

Failed: Timed out sending 'list_disk' to vm-uuid after 45 seconds (00:18:15) #280

Closed pdelagrave closed 6 years ago

pdelagrave commented 7 years ago

Versions (please add them if you have more releases for this issue)

CPI Version: 23 BOSH Version: 260.7.0 CF Version: 246.0.19 Diego Version: 0.1491.17

Stemcell

Version: 3312.28 Distro: ubuntu

Environment

Issue Details

Randomly happen during installation

Started creating missing vms > cf-mysql-broker/e1768d32-0f20-43bd-b163-31534bc065e0 (0)
  Started creating missing vms > cf-mysql-broker/d19c2317-06a5-4d91-8fa5-6623d9f13a9c (1)
     Done creating missing vms > mysql/6ce88c0b-a04b-490e-9343-35eed0d4b8ed (2) (00:01:39)
     Done creating missing vms > mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0) (00:02:00)
     Done creating missing vms > cf-mysql-broker/e1768d32-0f20-43bd-b163-31534bc065e0 (0) (00:02:11)
     Done creating missing vms > proxy/83e57882-cdb9-4d85-9780-efc03c8fa4da (1) (00:04:15)
     Done creating missing vms > mysql/474e4c7d-bdb8-42d8-b727-412f10639d65 (1) (00:04:16)
     Done creating missing vms > cf-mysql-broker/d19c2317-06a5-4d91-8fa5-6623d9f13a9c (1) (00:04:20)
     Done creating missing vms > monitoring/e844cc5d-6c9b-4a08-85a1-5f04db18fa1c (0) (00:04:21)
     Done creating missing vms > proxy/773eef33-5079-4acd-a2b2-e7d36aa93288 (0) (00:04:28)
     Done creating missing vms (00:04:28)

  Started updating instance mysql
  Started updating instance mysql > mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0) (canary). Failed: Timed out sending 'list_disk' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds (00:18:15)

Error 450002: Timed out sending 'list_disk' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds

Task 59 error

For a more detailed error report, run: bosh task 59 --debug

Part of bosh task 59 --debug:

D, [2017-06-06 10:49:55 #24134] [] DEBUG -- DirectorJobRunner: Renewing lock: lock:deployment:p-mysql-97de45ad1b322075a316
D, [2017-06-06 10:49:55 #24134] [] DEBUG -- DirectorJobRunner: (0.000229s) SELECT NULL
D, [2017-06-06 10:49:55 #24134] [] DEBUG -- DirectorJobRunner: (0.000228s) SELECT NULL
D, [2017-06-06 10:49:55 #24134] [] DEBUG -- DirectorJobRunner: (0.000131s) SELECT NULL
D, [2017-06-06 10:49:55 #24134] [] DEBUG -- DirectorJobRunner: (0.047339s) UPDATE "locks" SET "expired_at" = '2017-06-06 10:50:06.562288+0000' WHERE (("name" = 'lock:deployment:p-mysql-97de45ad1b322075a316') AND ("uid" = '33798aac-6d0c-48b3-85ba-a0cdce40ab42'))
D, [2017-06-06 10:49:59 #24134] [canary_update(mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0))] DEBUG -- DirectorJobRunner: (0.000228s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [canary_update(mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0))] DEBUG -- DirectorJobRunner: (0.000095s) BEGIN
D, [2017-06-06 10:49:59 #24134] [canary_update(mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0))] DEBUG -- DirectorJobRunner: (0.000420s) INSERT INTO "events" ("parent_id", "timestamp", "user", "action", "object_type", "object_name", "error", "task", "deployment", "instance", "context_json") VALUES (379, '2017-06-06 10:49:59.570766+0000', 'ops_manager', 'create', 'instance', 'mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4', 'Timed out sending ''list_disk'' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds', '59', 'p-mysql-97de45ad1b322075a316', 'mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4', '{}') RETURNING *
D, [2017-06-06 10:49:59 #24134] [canary_update(mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0))] DEBUG -- DirectorJobRunner: (0.005156s) COMMIT
E, [2017-06-06 10:49:59 #24134] [canary_update(mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 (0))] ERROR -- DirectorJobRunner: Error updating canary instance: #<Bosh::Director::RpcTimeout: Timed out sending 'list_disk' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds>
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:238:in `block in handle_method'
/var/vcap/packages/ruby/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:233:in `handle_method'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:302:in `handle_message_with_retry'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:353:in `start_task'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:319:in `send_message'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:67:in `list_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:168:in `agent_mounted_disks'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:117:in `unmount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:205:in `unmount_and_detach_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:182:in `rescue in mount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:177:in `mount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:91:in `attach_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:35:in `block in update_persistent_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:26:in `each'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:26:in `update_persistent_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater.rb:95:in `block in update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater/instance_state.rb:5:in `with_instance_update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater/instance_state.rb:11:in `with_instance_update_and_event_creation'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater.rb:111:in `update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:112:in `block (2 levels) in update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:110:in `block in update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/event_log.rb:99:in `advance_and_track'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:109:in `update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:104:in `block (2 levels) in update_canaries'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:77:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:63:in `block in create_thread'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
E, [2017-06-06 10:49:59 #24134] [] ERROR -- DirectorJobRunner: Worker thread raised exception: Timed out sending 'list_disk' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds - /var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:238:in `block in handle_method'
/var/vcap/packages/ruby/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:233:in `handle_method'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:302:in `handle_message_with_retry'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:353:in `start_task'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:319:in `send_message'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:67:in `list_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:168:in `agent_mounted_disks'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:117:in `unmount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:205:in `unmount_and_detach_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:182:in `rescue in mount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:177:in `mount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:91:in `attach_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:35:in `block in update_persistent_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:26:in `each'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:26:in `update_persistent_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater.rb:95:in `block in update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater/instance_state.rb:5:in `with_instance_update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater/instance_state.rb:11:in `with_instance_update_and_event_creation'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater.rb:111:in `update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:112:in `block (2 levels) in update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:110:in `block in update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/event_log.rb:99:in `advance_and_track'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:109:in `update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:104:in `block (2 levels) in update_canaries'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:77:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:63:in `block in create_thread'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
D, [2017-06-06 10:49:59 #24134] [] DEBUG -- DirectorJobRunner: Thread is no longer needed, cleaning up
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: Shutting down pool
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000670s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000896s) SELECT "stemcells".* FROM "stemcells" INNER JOIN "deployments_stemcells" ON ("deployments_stemcells"."stemcell_id" = "stemcells"."id") WHERE ("deployments_stemcells"."deployment_id" = 3)
D, [2017-06-06 10:49:59 #24134] [] DEBUG -- DirectorJobRunner: Lock renewal thread exiting
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000197s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000201s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000167s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.003648s) DELETE FROM "locks" WHERE (("name" = 'lock:deployment:p-mysql-97de45ad1b322075a316') AND ("uid" = '33798aac-6d0c-48b3-85ba-a0cdce40ab42'))
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: Deleted lock: lock:deployment:p-mysql-97de45ad1b322075a316 uid: 33798aac-6d0c-48b3-85ba-a0cdce40ab42
I, [2017-06-06 10:49:59 #24134] [task:59]  INFO -- DirectorJobRunner: sending update deployment error event
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: SENT: hm.director.alert {"id":"300b869d-a0d7-4b51-b5aa-4cccd1da092f","severity":3,"source":"director","title":"director - error during update deployment","summary":"Error during update deployment for 'p-mysql-97de45ad1b322075a316' against Director '5988dc8a-d2da-4bc5-9f50-5f6a08568269': #<Bosh::Director::RpcTimeout: Timed out sending 'list_disk' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds>","created_at":1496746199}
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000851s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000123s) BEGIN
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000291s) INSERT INTO "events" ("parent_id", "timestamp", "user", "action", "object_type", "object_name", "error", "task", "deployment", "instance", "context_json") VALUES (330, '2017-06-06 10:49:59.587302+0000', 'ops_manager', 'create', 'deployment', 'p-mysql-97de45ad1b322075a316', 'Timed out sending ''list_disk'' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds', '59', 'p-mysql-97de45ad1b322075a316', NULL, '{"before":{},"after":{"releases":["fim/1.1.2","ipsec/1.6.3","clamav/1.1.6","cf-mysql/34.8.0","mysql-backup/1.32.0","service-backup/18.0.4","mysql-monitoring/8.1.0","consul/163","loggregator/65"],"stemcells":["bosh-azure-hyperv-ubuntu-trusty-go_agent/3312.28"]}}') RETURNING *
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.003178s) COMMIT
E, [2017-06-06 10:49:59 #24134] [task:59] ERROR -- DirectorJobRunner: Timed out sending 'list_disk' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:238:in `block in handle_method'
/var/vcap/packages/ruby/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:233:in `handle_method'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:302:in `handle_message_with_retry'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:353:in `start_task'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:319:in `send_message'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/agent_client.rb:67:in `list_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:168:in `agent_mounted_disks'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:117:in `unmount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:205:in `unmount_and_detach_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:182:in `rescue in mount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:177:in `mount_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:91:in `attach_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:35:in `block in update_persistent_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:26:in `each'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/disk_manager.rb:26:in `update_persistent_disk'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater.rb:95:in `block in update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater/instance_state.rb:5:in `with_instance_update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater/instance_state.rb:11:in `with_instance_update_and_event_creation'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/instance_updater.rb:111:in `update'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:112:in `block (2 levels) in update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_formatter.rb:49:in `with_thread_name'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:110:in `block in update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/event_log.rb:99:in `advance_and_track'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:109:in `update_canary_instance'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh-director-260.7.0/lib/bosh/director/job_updater.rb:104:in `block (2 levels) in update_canaries'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:77:in `block (2 levels) in create_thread'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/bosh_common-260.7.0/lib/common/thread_pool.rb:63:in `block in create_thread'
/var/vcap/packages/director/gem_home/ruby/2.3.0/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000474s) SELECT NULL
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000135s) BEGIN
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.000433s) UPDATE "tasks" SET "state" = 'error', "timestamp" = '2017-06-06 10:49:59.593567+0000', "description" = 'create deployment', "result" = 'Timed out sending ''list_disk'' to c4e6e2ff-8ee2-463b-a1d2-f1190b4e21e1 after 45 seconds', "output" = '/var/vcap/store/director/tasks/59', "checkpoint_time" = '2017-06-06 10:14:50.156963+0000', "type" = 'update_deployment', "username" = 'ops_manager', "deployment_name" = 'p-mysql-97de45ad1b322075a316', "started_at" = '2017-06-06 10:14:50.156890+0000' WHERE ("id" = 59)
D, [2017-06-06 10:49:59 #24134] [task:59] DEBUG -- DirectorJobRunner: (0.003641s) COMMIT
I, [2017-06-06 10:49:59 #24134] []  INFO -- DirectorJobRunner: Task took 35 minutes 9.444713100000172 seconds to process.

Task 59 error
AbelHu commented 7 years ago

@pdelagrave If you assure that your stemcell version is 3312.28, this issue should have been fixed and it may be a different issue. Could you share the bosh-agent's logs of the VM mysql/33e8e561-233c-4a26-9f7e-4a6fbf978ce4 with us for advanced investigation? The bosh-agent's logs inside the VM should be under this path /var/vcap/bosh/log/.

If the VM has been deleted, please update your bosh.yml by adding below config item in director property, redeploy your BOSH director and then reproduce the issue.

  director:
    debug:
      keep_unreachable_vms: true
pdelagrave commented 7 years ago

@AbelHu The VM isn't deleted when the problem happen. We have been told that the VM boot diagnostic log would be useful to get for investigation. I see it can be enabled in the Azure UI but then that would be only after the fact so I'm not sure it would be useful. Actually, trying to enable it on a VM that experienced the problem cause the Azure UI to be unresponsive.

Is there a way to configure the CPI so the VM boot diagnostic log is enabled before their creation?

Thanks

Pierre

AbelHu commented 7 years ago

@pdelagrave A work item is created. We try to support VM boot diagnostic in next version.

ghost commented 7 years ago

I got similar issue:

bosh: 263.4.0 bosh-azure-cpi: 29 bosh stemcell: 3445.16

Task 418

Task 418 | 12:19:39 | Preparing deployment: Preparing deployment (00:00:01)
Task 418 | 12:19:41 | Preparing package compilation: Finding packages to compile (00:00:01)
Task 418 | 12:19:42 | Creating missing vms: proxy/899c7509-1914-4ddf-9116-2b28a7bad042 (1)
Task 418 | 12:19:42 | Creating missing vms: cf-mysql-broker/cf286c3e-e874-4b43-bca4-cd566b20b627 (1)
Task 418 | 12:22:27 | Creating missing vms: proxy/899c7509-1914-4ddf-9116-2b28a7bad042 (1) (00:02:45)
Task 418 | 12:22:52 | Creating missing vms: cf-mysql-broker/cf286c3e-e874-4b43-bca4-cd566b20b627 (1) (00:03:10)
Task 418 | 12:22:52 | Updating instance mysql: mysql/a65780fc-0158-4216-9db5-543e447d87a0 (0) (canary) (00:13:09)
                    L Error: Timed out sending 'list_disk' to fe8e85f0-93a9-47c9-b669-58e5112237e9 after 45 seconds
Task 418 | 12:36:01 | Error: Timed out sending 'list_disk' to fe8e85f0-93a9-47c9-b669-58e5112237e9 after 45 seconds

Task 418 Started  Tue Nov 14 12:19:39 UTC 2017
Task 418 Finished Tue Nov 14 12:36:01 UTC 2017
Task 418 Duration 00:16:22
Task 418 error
AbelHu commented 7 years ago

@nevenc-pivotal It is a known issue and we are working on the fix now.

bingosummer commented 6 years ago

@pdelagrave We merged a workaround recently. Could you please check it? If it works, we will close the issue.

pdelagrave commented 6 years ago

@bingosummer we'll test it as soon as there's a PCF version shipped with the CPI containing the fix. Thanks!

gossion commented 6 years ago

The issue was already solved. Close it. If you see the issue again, feel free to reopen it.