logical volume "volume-x" already exists in volume group "y"

[Joe Gordon]

Seen during tempest devstack:

Logstash query: "already exists in volume group" AND @fields.build_status:"FAILURE" AND @fields.loglevel:"ERROR" AND @fields.filename:"logs/screen-c-vol.txt"

http://logs.openstack.org/62/45462/8/check/gate-tempest-devstack-vm-postgres-full/743eebf/logs/screen-c-vol.txt.gz#_2013-09-19_22_06_15_474

2013-09-19 22:06:15.474 22515 ERROR cinder.openstack.common.rpc.amqp [req-a708aa9d-8f7a-45a3-b0e2-c7617da0d2fc 42421857795f42a89c8863ba1cc54d36 3c113e39d0604d43956554ee3cdfa401] Exception during message handling
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp Traceback (most recent call last):
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/openstack/common/rpc/amqp.py", line 441, in _process_data
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp **args)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/openstack/common/rpc/dispatcher.py", line 148, in dispatch
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp return getattr(proxyobj, method)(ctxt, **kwargs)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/manager.py", line 222, in create_volume
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp flow.run(context.elevated())
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/decorators.py", line 105, in wrapper
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp return f(self, *args, **kwargs)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 232, in run
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp run_it(r)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 212, in run_it
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp self.rollback(context, cause)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp self.gen.next()
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/patterns/linear_flow.py", line 172, in run_it
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp result = runner(context, *args, **kwargs)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/taskflow/utils.py", line 260, in __call__
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp self.result = self.task(*args, **kwargs)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py", line 1462, in __call__
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp **volume_spec)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/flows/create_volume/__init__.py", line 1420, in _create_from_image
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp model_update = self.driver.create_volume(volume_ref)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 166, in create_volume
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp mirror_count)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/volume/drivers/lvm.py", line 155, in _create_volume
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp vg_ref.create_volume(name, size, lvm_type, mirror_count)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/brick/local_dev/lvm.py", line 368, in create_volume
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp run_as_root=True)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/utils.py", line 142, in execute
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp return processutils.execute(*cmd, **kwargs)
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp File "/opt/stack/new/cinder/cinder/openstack/common/processutils.py", line 173, in execute
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp cmd=' '.join(cmd))
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp ProcessExecutionError: Unexpected error while running command.
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp Command: sudo cinder-rootwrap /etc/cinder/rootwrap.conf lvcreate -n volume-8bae166b-91f0-44fe-8a3b-b3fa6cf5180e stack-volumes -L 1g
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp Exit code: 5
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp Stdout: ''
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp Stderr: ' Logical volume "volume-8bae166b-91f0-44fe-8a3b-b3fa6cf5180e" already exists in volume group "stack-volumes"\n'
2013-09-19 22:06:15.474 22515 TRACE cinder.openstack.common.rpc.amqp

Logstash says this has happend 8 times in the past 4 hours alone

[Joe Gordon (jogo)]

Confirmed via logstash / tempest /jenkins

[John Griffith (john-griffith)]

Funny, I just noticed this last night while looking at another problem and was planning to work on it next. The issue here is that again since a white-list of exceptions was used in the create task-flow, anything that raises that isn't in that white list will result in a retry attempt, and in this case (an many others) the lvcreate succeeded so we end up with this message.

I have a fix in progress.