ns_create stuck in pending state if vnf creation failed

[dharmendra]

On-board a vnfd with a sample template, and then removed the VNFD's flavor.

After that while creating NS, tacker log generated some tracebacks and NS create stuck in PENDING_CREATE state.

2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00mTraceback (most recent call last):^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/api/v1/resource.py", line 83, in resource^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m result = method(request=request, **args)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/api/v1/base.py", line 395, in create^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m obj = obj_creator(request.context, **kwargs)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/vnfm/plugin.py", line 364, in create_vnf^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m vnf_dict = self._create_vnf(context, vnf_info, vim_auth, infra_driver)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/vnfm/plugin.py", line 323, in _create_vnf^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m self.delete_vnf(context, vnf_id)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m self.force_reraise()^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m six.reraise(self.type_, self.value, self.tb)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/vnfm/plugin.py", line 320, in _create_vnf^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m context=context, vnf=vnf_dict, auth_attr=vim_auth)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/common/driver_manager.py", line 70, in invoke^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m return getattr(driver, method_name)(**kwargs)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/common/log.py", line 35, in wrapper^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m return method(*args, **kwargs)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/vnfm/infra_drivers/openstack/openstack.py", line 104, in create^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m stack = self._create_stack(heatclient, tth.vnf, tth.fields)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/common/log.py", line 35, in wrapper^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m return method(*args, **kwargs)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/vnfm/infra_drivers/openstack/openstack.py", line 120, in _create_stack^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m stack = heatclient.create(fields)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/vnfm/infra_drivers/openstack/heat_client.py", line 44, in create^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m raise vnfm.HeatClientException(msg=value)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00mHeatClientException: ERROR: Property error: : resources.VDU1.properties.flavor: : Error validating value 'dk_flavor': No Flavor matching {'name': u'dk_flavor'}. (HTTP 404)^M
2017-02-07 22:22:10.959 TRACE tacker.api.v1.resource ^[[01;35m^[[00m^M
2017-02-07 22:22:10.963 INFO tacker.wsgi [^[[01;36mreq-5d9f19f2-fd6d-4317-9f8c-9a4989a5fab2 ^[[00;36madmin ebd9959cccbd4f1281c85f9229d37c1f] ^[[01;35m192.168.200.2 - - [07/Feb/2017 22:22:10] "POST //v1.0/vnfs.json HTTP/1.1" 500 445 2.851716^[[00m^M

2017-02-07 22:22:52.314 DEBUG tacker.db.nfvo.ns_db [^[[00;36m-] ^[[01;35mns ID 45e1844d-2a66-4d18-839c-899bf27ad127^[[00m ^[[00;33mfrom (pid=13196) create_ns_post /opt/stack/tacker/tacker/db/nfvo/ns_db.py:253^[[00m^M
Traceback (most recent call last):^M
  File "/usr/local/lib/python2.7/dist-packages/eventlet/greenpool.py", line 82, in _spawn_n_impl^M
    func(*args, **kwargs)^M
  File "/opt/stack/tacker/tacker/nfvo/nfvo_plugin.py", line 625, in _create_ns_wait^M
    vnfd_dict, error_reason)^M
  File "/opt/stack/tacker/tacker/db/nfvo/ns_db.py", line 261, in create_ns_post^M
    output['mgmt_url_' + instance].strip())^M
KeyError: 'mgmt_url_VNF2'^M

After that when tried to delete the ns, it was showing internal server error and tacker logs showing traceback:

2017-02-07 22:32:20.028 ERROR tacker.api.v1.resource [^[[01;36mreq-65325410-b9eb-42b3-8087-8c7bb7133c92 ^[[00;36madmin ebd9959cccbd4f1281c85f9229d37c1f] ^[[01;35mdelete failed^[[00m^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00mTraceback (most recent call last):^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/api/v1/resource.py", line 83, in resource^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m result = method(request=request, **args)^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/api/v1/base.py", line 421, in delete^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m obj_deleter(request.context, id, **kwargs)^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/common/log.py", line 35, in wrapper^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m return method(*args, **kwargs)^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/nfvo/nfvo_plugin.py", line 668, in delete_ns^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m kwargs={'ns': ns})^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/common/driver_manager.py", line 70, in invoke^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m return getattr(driver, method_name)(**kwargs)^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/nfvo/drivers/vim/openstack_driver.py", line 469, in prepare_and_create_workflow^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m wg.task(**kwargs)^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/opt/stack/tacker/tacker/nfvo/drivers/workflow/workflow_generator.py", line 181, in delete_vnf^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m vnf_ids = ast.literal_eval(ns['vnf_ids'])^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/usr/lib/python2.7/ast.py", line 80, in literal_eval^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m return _convert(node_or_string)^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m File "/usr/lib/python2.7/ast.py", line 79, in _convert^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m raise ValueError('malformed string')^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00mValueError: malformed string^M
2017-02-07 22:32:20.028 TRACE tacker.api.v1.resource ^[[01;35m^[[00m^M

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/430475

[yong sheng gong (gongysh)]

I am little confused with the steps to reproduce this bug:
'and then removed the VNFD's flavor.'
what is VNFD's flavor?

[dharmendra (dharmendra-kushwaha)]

Sorry for miss communication, here the flavor is for nova flavor.
As mentioned in below template section, I had created a flavor named "my_flavor".

  node_templates:
    VDU1:
      type: tosca.nodes.nfv.VDU.Tacker
      properties:
        image: cirros-0.3.4-x86_64-uec
        flavor: my_flavor
        availability_zone: nova
        mgmt_driver: noop
        config: |
          param0: key1
          param1: key2

Before ns-create, I deleted it from nova side.
.. nova flavor-delete my_flavor

But actually my point is not about flavor only.
In case any exception in VNF create, this error will be produced.

[Sridhar Ramaswamy (srics-r)]

This is a valid bug, very easy for tacker users to hit (especially new users trying NSD feature).

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/430475
Committed: https://git.openstack.org/cgit/openstack/tacker/commit/?id=850858a96713d6be1a356a9838c898cf0aa8c786
Submitter: Jenkins
Branch: master

commit 850858a96713d6be1a356a9838c898cf0aa8c786
Author: Dharmendra Kushwaha <email address hidden>
Date: Tue Feb 7 23:23:19 2017 +0000

    Fix ns_create stuck in pending state issue

    while deploying network service if vnf creation raised exception,
    ns_create stuck in PENDING_CREATE state. Fixing this issue.

    Change-Id: I647993ae888084b167ee08b73a531e92528de774
    Closes-Bug: #1662704

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tacker 0.7.0 release.