Deployment failed because of virtual_ips task

[Evgeny Sboychakov]

Steps to reproduce:
1. Create cluster
2. Add 1 Controller
3. Add 3 Computes
4. No bonding. No DVR. All other settings are default.
5. Run network verification
6. Deploy the cluster

Expected result:
Deploy passed.

Actual result:
Deploy failed.

In Astute.log:
2015-12-03 12:36:32 INFO [339] Casting message to Nailgun:
{"method"=>"deploy_resp",
 "args"=>
  {"task_uuid"=>"96d6685a-44d6-4119-a2d4-7c8c3941b7b7",
   "nodes"=>
    [{"uid"=>"7",
      "progress"=>0,
      "status"=>"deploying",
      "role"=>"primary-controller",
      "task"=>
       {"priority"=>1400,
        "type"=>"puppet",
        "uids"=>["7"],
        "parameters"=>
         {"puppet_modules"=>"/etc/puppet/modules",
          "puppet_manifest"=>
           "/etc/puppet/modules/osnailyfacter/modular/virtual_ips/virtual_ips.pp",
          "timeout"=>3600,
          "cwd"=>"/"}}}]}}

2015-12-03 13:08:10 INFO [339] Retrying to run puppet for following error nodes: 7
2015-12-03 13:36:30 ERROR [339] Timeout of deployment is exceeded.
2015-12-03 13:36:30 INFO [339] Casting message to Nailgun:
{"method"=>"deploy_resp",
 "args"=>
  {"task_uuid"=>"96d6685a-44d6-4119-a2d4-7c8c3941b7b7",
   "nodes"=>
    [{"uid"=>"7",
      "status"=>"error",
      "role"=>"primary-controller",
      "error_type"=>"deploy"}]}}

2015-12-03 13:36:30 INFO [339] Casting message to Nailgun:
{"method"=>"deploy_resp",
 "args"=>
  {"task_uuid"=>"96d6685a-44d6-4119-a2d4-7c8c3941b7b7",
   "status"=>"error",
   "error"=>"Timeout of deployment is exceeded."}}

In puppet.log from Controller node:
2015-12-03 13:39:47 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter_pub]/Service[vip__vrouter_pub]/ensure (err): change from stopped to running failed: Execution timeout after 600 seconds!
2015-12-03 13:39:47 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter_pub]/Service[vip__vrouter_pub] (info): Evaluated in 622.49 seconds
2015-12-03 13:39:47 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter]/Service[vip__vrouter] (info): Starting to evaluate the resource
2015-12-03 13:39:47 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter]/Service[vip__vrouter] (notice): Dependency Service[vip__vrouter_pub] has failures: true
2015-12-03 13:39:47 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter]/Service[vip__vrouter] (warning): Skipping because of failed dependencies
2015-12-03 13:39:47 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter]/Service[vip__vrouter] (info): Evaluated in 0.00 seconds
2015-12-03 13:39:47 +0000 Cluster::Virtual_ip[vrouter] (info): Starting to evaluate the resource
2015-12-03 13:39:47 +0000 Cluster::Virtual_ip[vrouter] (debug): The container Class[Main] will propagate my refresh event
2015-12-03 13:39:47 +0000 Cluster::Virtual_ip[vrouter] (info): Evaluated in 0.00 seconds
2015-12-03 13:39:47 +0000 Puppet (debug): Prefetching crm resources for cs_rsc_colocation
2015-12-03 13:39:47 +0000 Puppet (debug): Executing '/usr/sbin/pcs property show dc-version'
2015-12-03 13:39:49 +0000 Puppet (debug): Executing '/usr/sbin/pcs property show dc-version'
2015-12-03 13:39:51 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter_pub]/Cs_rsc_colocation[vip__vrouter-with-vip__vrouter_pub] (info): Starting to evaluate the resource
2015-12-03 13:39:51 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter_pub]/Cs_rsc_colocation[vip__vrouter-with-vip__vrouter_pub] (notice): Dependency Service[vip__vrouter_pub] has failures: true
2015-12-03 13:39:51 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter_pub]/Cs_rsc_colocation[vip__vrouter-with-vip__vrouter_pub] (warning): Skipping because of failed dependencies
2015-12-03 13:39:51 +0000 /Stage[main]/Main/Cluster::Virtual_ip[vrouter_pub]/Cs_rsc_colocation[vip__vrouter-with-vip__vrouter_pub] (info): Evaluated in 0.00 seconds
2015-12-03 13:39:51 +0000 Cluster::Virtual_ip[vrouter_pub] (info): Starting to evaluate the resource
2015-12-03 13:39:51 +0000 Cluster::Virtual_ip[vrouter_pub] (debug): The container Class[Main] will propagate my refresh event
2015-12-03 13:39:51 +0000 Cluster::Virtual_ip[vrouter_pub] (info): Evaluated in 0.00 seconds
2015-12-03 13:39:51 +0000 Class[Main] (info): Starting to evaluate the resource
2015-12-03 13:39:51 +0000 Class[Main] (debug): The container Stage[main] will propagate my refresh event
2015-12-03 13:39:51 +0000 Class[Main] (info): Evaluated in 0.00 seconds
2015-12-03 13:39:51 +0000 Stage[main] (info): Starting to evaluate the resource
2015-12-03 13:39:51 +0000 Stage[main] (info): Evaluated in 0.00 seconds
2015-12-03 13:39:51 +0000 Puppet (debug): Finishing transaction 29670260
2015-12-03 13:39:51 +0000 Puppet (debug): Storing state
2015-12-03 13:39:51 +0000 Puppet (debug): Stored state in 0.09 seconds
2015-12-03 13:39:51 +0000 Puppet (notice): Finished catalog run in 1896.77 seconds
2015-12-03 13:39:51 +0000 Puppet (debug): Executing '/bin/true'

fuel details:
api: '1'
auth_required: true
feature_groups:
- experimental
- advanced
openstack_version: 2015.1.0-8.0
release: '8.0'

build number: 324

[Evgeny Sboychakov (ysboychakov)]

puppet.log from Controller node

[Evgeny Sboychakov (ysboychakov)]

Unfortunately can't generate the Diagnostic Snapshot.
Please refer relevant bug: https://bugs.launchpad.net/fuel/+bug/1522483

[Kyrylo Galanov (kgalanov)]

Hi,

Apparently, this is CentOS7 build. Pacemaker tries to call upstart scripts which were replaced by systemd
http://paste.openstack.org/show/481136/

--
Kyrylo

[Kyrylo Galanov (kgalanov)]

I will verify after the bug is fixed https://bugs.launchpad.net/fuel/+bug/1523523

[Kyrylo Galanov (kgalanov)]

It was not confirmed with the latest ISO.