juju tries to delete in-use security groups

Bug #1017801 reported by Robert Collins
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
pyjuju
Fix Released
Medium
Jim Baker
0.5
Fix Released
Medium
Unassigned

Bug Description

I see this from time to time on my openstack logs:
2012-06-26 16:14:17 ERROR nova.api.ec2 [req-7c2edc93-cb70-4dfd-801a-a9b205c5a1ea demo demo] Unexpected error raised: Group not valid. Reason: Security group is still in use
2012-06-26 16:14:17 TRACE nova.api.ec2 Traceback (most recent call last):
2012-06-26 16:14:17 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/ec2/__init__.py", line 471, in __call__
2012-06-26 16:14:17 TRACE nova.api.ec2 result = api_request.invoke(context)
2012-06-26 16:14:17 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/ec2/apirequest.py", line 81, in invoke
2012-06-26 16:14:17 TRACE nova.api.ec2 result = method(context, **args)
2012-06-26 16:14:17 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/ec2/cloud.py", line 654, in delete_security_group
2012-06-26 16:14:17 TRACE nova.api.ec2 self.security_group_api.destroy(context, security_group)
2012-06-26 16:14:17 TRACE nova.api.ec2 File "/opt/stack/nova/nova/compute/api.py", line 2027, in destroy
2012-06-26 16:14:17 TRACE nova.api.ec2 self.raise_invalid_group(msg)
2012-06-26 16:14:17 TRACE nova.api.ec2 File "/opt/stack/nova/nova/api/ec2/cloud.py", line 1555, in raise_invalid_group
2012-06-26 16:14:17 TRACE nova.api.ec2 raise exception.InvalidGroup(reason=msg)
2012-06-26 16:14:17 TRACE nova.api.ec2 InvalidGroup: Group not valid. Reason: Security group is still in use
2012-06-26 16:14:17 TRACE nova.api.ec2
2012-06-26 16:14:17 ERROR nova.api.ec2 [req-7c2edc93-cb70-4dfd-801a-a9b205c5a1ea demo demo] Environment: {"CONTENT_TYPE": "text/plain", "SCRIPT_NAME": "/services/Cloud", "REQUEST_METHOD": "GET", "HTTP_HOST": "192.168.1.102:8773", "PATH_INFO": "", "SERVER_PROTOCOL": "HTTP/1.0", "QUERY_STRING": "AWSAccessKeyId=6d9eda54387c45939c0401315229b955&Action=DeleteSecurityGroup&GroupName=juju-devstack-7&Signature=FKSIi%2BoCLONFbXsML07Tt4yDwcB4EKVkWCK8090ep%2Fw%3D&SignatureMethod=HmacSHA256&SignatureVersion=2&Timestamp=2012-06-26T04%3A14%3A17Z&Version=2008-12-01", "HTTP_USER_AGENT": "Twisted PageGetter", "SERVER_NAME": "192.168.1.102", "REMOTE_ADDR": "10.0.0.3", "wsgi.url_scheme": "http", "SERVER_PORT": "8773", "GATEWAY_INTERFACE": "CGI/1.1"}
2012-06-26 16:14:17 ERROR nova.api.ec2 [req-7c2edc93-cb70-4dfd-801a-a9b205c5a1ea demo demo] UnknownError: An unknown error has occurred. Please try your request again.

Note that it happens sometime after a deploy to a unit has failed with a hung or wedged machine. At a guess, the wedged machine holds a reference and juju is trying to clean up before getting things going. Problem is, that hung instance needs to be cleared first.

2012-06-26 04:18:18,491: juju.agents.provision@INFO: Starting machine id:7 ...
Juju sees the error (from provisioning.log):
2012-06-26 04:18:18,851: juju.ec2@DEBUG: Cannot delete security group juju-devstack-7: Error Message: An unknown error has occurred. Please try your request again.
2012-06-26 04:18:18,854: juju.agents.provision@ERROR: Cannot process machine 7
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/juju/agents/provision.py", line 187, in process_machines
    machine_state_id, provider_machines)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/agents/provision.py", line 228, in process_machine
    {"machine-id": machine_state.id, "constraints": constraints})
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/common/launch.py", line 64, in run
    machines = yield self.start_machine(machine_id, zookeepers)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/ec2/launch.py", line 42, in start_machine
    security_groups = yield self._ensure_groups(machine_id)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/ec2/launch.py", line 114, in _ensure_groups
    % (juju_machine_group, e.get_error_messages()))
ProviderInteractionError: Unexpected EC2Error deleting security group juju-devstack-7: An unknown error has occurred. Please try your request again.

Related branches

Revision history for this message
Robert Collins (lifeless) wrote :
Download full text (3.3 KiB)

This is the entire lead-up:
2012-06-26 04:08:42,305: juju.ec2@DEBUG: Creating juju machine security group juju-devstack-7
2012-06-26 04:08:42,531: juju.ec2@DEBUG: Launching with machine spec MachineSpec(instance_type='m1.small', image_id='ami-00000004')
2012-06-26 04:08:43,289: juju.state.expose@DEBUG: Assigned units for machine 7: old=None, new=set(['elasticsearch/0'])
2012-06-26 04:08:43,421: juju.state.expose@INFO: No provisioned machine for machine 7
2012-06-26 04:09:13,687: juju.agents.provision@INFO: Starting machine id:7 ...
2012-06-26 04:09:13,707: juju.ec2@WARNING: ssl-hostname-verification is disabled for this environment
2012-06-26 04:09:13,707: juju.ec2@WARNING: EC2 API calls not using secure transport
2012-06-26 04:09:13,708: juju.ec2@WARNING: S3 API calls not using secure transport
2012-06-26 04:09:13,708: juju.ec2@WARNING: Ubuntu Cloud Image lookups encrypted but not authenticated
2012-06-26 04:09:14,063: juju.ec2@DEBUG: Cannot delete security group juju-devstack-7: Error Message: An unknown error has occurred. Please try your request again.
2012-06-26 04:09:14,065: juju.agents.provision@ERROR: Cannot process machine 7
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/juju/agents/provision.py", line 187, in process_machines
    machine_state_id, provider_machines)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/agents/provision.py", line 228, in process_machine
    {"machine-id": machine_state.id, "constraints": constraints})
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/common/launch.py", line 64, in run
    machines = yield self.start_machine(machine_id, zookeepers)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/ec2/launch.py", line 42, in start_machine
    security_groups = yield self._ensure_groups(machine_id)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/ec2/launch.py", line 114, in _ensure_groups
    % (juju_machine_group, e.get_error_messages())...

Read more...

Revision history for this message
Kapil Thangavelu (hazmat) wrote : Re: [Bug 1017801] Re: juju tries to delete in-use security groups
Download full text (4.1 KiB)

juju will detect async if a machine with the group exists that is not known
and kill it. the create path is different. this create/destroy group logic
is subject to change shortly to avoid waits and destroying groups vs. just
clearing the group and proceeding.
-k

On Mon, Jun 25, 2012 at 9:21 PM, Robert Collins
<email address hidden>wrote:

> This is the entire lead-up:
> 2012-06-26 04:08:42,305: juju.ec2@DEBUG: Creating juju machine security
> group juju-devstack-7
> 2012-06-26 04:08:42,531: juju.ec2@DEBUG: Launching with machine spec
> MachineSpec(instance_type='m1.small', image_id='ami-00000004')
> 2012-06-26 04:08:43,289: juju.state.expose@DEBUG: Assigned units for
> machine 7: old=None, new=set(['elasticsearch/0'])
> 2012-06-26 04:08:43,421: juju.state.expose@INFO: No provisioned machine
> for machine 7
> 2012-06-26 04:09:13,687: juju.agents.provision@INFO: Starting machine
> id:7 ...
> 2012-06-26 04:09:13,707: juju.ec2@WARNING: ssl-hostname-verification is
> disabled for this environment
> 2012-06-26 04:09:13,707: juju.ec2@WARNING: EC2 API calls not using secure
> transport
> 2012-06-26 04:09:13,708: juju.ec2@WARNING: S3 API calls not using secure
> transport
> 2012-06-26 04:09:13,708: juju.ec2@WARNING: Ubuntu Cloud Image lookups
> encrypted but not authenticated
> 2012-06-26 04:09:14,063: juju.ec2@DEBUG: Cannot delete security group
> juju-devstack-7: Error Message: An unknown error has occurred. Please try
> your request again.
> 2012-06-26 04:09:14,065: juju.agents.provision@ERROR: Cannot process
> machine 7
> Traceback (most recent call last):
> File "/usr/lib/python2.7/dist-packages/juju/agents/provision.py", line
> 187, in process_machines
> machine_state_id, provider_machines)
> File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line
> 1037, in _inlineCallbacks
> result = result.throwExceptionIntoGenerator(g)
> File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line
> 382, in throwExceptionIntoGenerator
> return g.throw(self.type, self.value, self.tb)
> File "/usr/lib/python2.7/dist-packages/juju/agents/provision.py", line
> 228, in process_machine
> {"machine-id": machine_state.id, "constraints": constraints})
> File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line
> 1037, in _inlineCallbacks
> result = result.throwExceptionIntoGenerator(g)
> File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line
> 382, in throwExceptionIntoGenerator
> return g.throw(self.type, self.value, self.tb)
> File "/usr/lib/python2.7/dist-packages/juju/providers/common/launch.py",
> line 64, in run
> machines = yield self.start_machine(machine_id, zookeepers)
> File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line
> 1037, in _inlineCallbacks
> result = result.throwExceptionIntoGenerator(g)
> File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line
> 382, in throwExceptionIntoGenerator
> return g.throw(self.type, self.value, self.tb)
> File "/usr/lib/python2.7/dist-packages/juju/providers/ec2/launch.py",
> line 42, in start_machine
> security_groups = yield self._ensure_groups(machine_id)
> File "/usr/lib/pytho...

Read more...

Revision history for this message
Gustavo Niemeyer (niemeyer) wrote :

Is someone working on it then Kapil? Would you mind to update the bug status to reflect what's actually going on?

Jim Baker (jimbaker)
Changed in juju:
assignee: nobody → Jim Baker (jimbaker)
milestone: none → honolulu
status: New → In Progress
Revision history for this message
Jim Baker (jimbaker) wrote :

Security groups are no longer deleted, but reused.

Changed in juju:
status: In Progress → Fix Released
Changed in juju:
importance: Undecided → Medium
Revision history for this message
Ian D. Rossi (ian-d-rossi) wrote :
Download full text (13.9 KiB)

I have installed Openstack on a VM using devstack and have juju installed on my Ubuntu 12.10 laptop. I'm working with a fresh install of both Openstack and Juju with not VMs created. I bootstrapped my Openstack environment with a success message. But then, any deploy or subsequest bootstrap commands produce this error:

2013-02-09 11:56:52,050 ERROR Unexpected 400: '{"badRequest": {"message": "Security group is still in use", "code": 400}}'

The verbose output shows that a security group deletion was attempted:

2013-02-09 11:53:12,161 DEBUG access compute @ http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/os-security-groups/3
2013-02-09 11:53:12,161 DEBUG openstack: DELETE 'http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/os-security-groups/3'
2013-02-09 11:53:12,488 DEBUG openstack: 400 '{"badRequest": {"message": "Security group is still in use", "code": 400}}'

My question is, if security groups are no longer deleted, but reused, then why does this output show an attempt to delete?

Here is the entire verbose output and stack trace for a juju bootstrap command.

2013-02-09 11:53:10,715 DEBUG Initializing juju bootstrap runtime
2013-02-09 11:53:10,739 WARNING OpenStack identity service not using secure transport
2013-02-09 11:53:10,739 DEBUG openstack: using auth-mode 'userpass' with http://192.168.0.100:5000/v2.0/
2013-02-09 11:53:10,739 WARNING S3 API calls not using secure transport
2013-02-09 11:53:11,108 DEBUG openstack: authenticated til u'2013-02-10T16:51:51Z'
2013-02-09 11:53:11,109 WARNING OpenStack compute service not using secure transport
2013-02-09 11:53:11,109 DEBUG openstack: GET 'http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors'
2013-02-09 11:53:11,328 DEBUG openstack: 200 '{"flavors": [{"id": "1", "links": [{"href": "http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors/1", "rel": "self"}, {"href": "http://192.168.0.100:8774/3d30e458a99c4814977c35b46dcb3760/flavors/1", "rel": "bookmark"}], "name": "m1.tiny"}, {"id": "2", "links": [{"href": "http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors/2", "rel": "self"}, {"href": "http://192.168.0.100:8774/3d30e458a99c4814977c35b46dcb3760/flavors/2", "rel": "bookmark"}], "name": "m1.small"}, {"id": "3", "links": [{"href": "http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors/3", "rel": "self"}, {"href": "http://192.168.0.100:8774/3d30e458a99c4814977c35b46dcb3760/flavors/3", "rel": "bookmark"}], "name": "m1.medium"}, {"id": "4", "links": [{"href": "http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors/4", "rel": "self"}, {"href": "http://192.168.0.100:8774/3d30e458a99c4814977c35b46dcb3760/flavors/4", "rel": "bookmark"}], "name": "m1.large"}, {"id": "42", "links": [{"href": "http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors/42", "rel": "self"}, {"href": "http://192.168.0.100:8774/3d30e458a99c4814977c35b46dcb3760/flavors/42", "rel": "bookmark"}], "name": "m1.nano"}, {"id": "5", "links": [{"href": "http://192.168.0.100:8774/v2/3d30e458a99c4814977c35b46dcb3760/flavors/5", "rel": "self"}, {"href": "http://192.168.0.100:8774/3d30e458a99c4814977c35b46dcb3760/...

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.