RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 854242 - 3.1 - [vdsm] unable to delete multiple virtual disks with Wipe after delete (engine fence SPM)
Summary: 3.1 - [vdsm] unable to delete multiple virtual disks with Wipe after delete (...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: vdsm
Version: 6.3
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: rc
: ---
Assignee: Greg Padgett
QA Contact: vvyazmin@redhat.com
URL:
Whiteboard: storage
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-09-04 13:10 UTC by vvyazmin@redhat.com
Modified: 2022-07-09 05:39 UTC (History)
13 users (show)

Fixed In Version: vdsm-4.9.6-39.0
Doc Type: Bug Fix
Doc Text:
Previously, Red Hat Enterprise Virtualization did not adequately prioritize concurrent high I/O storage operations, like deleting and wiping multiple virtual machine disks. These operations resulted in large storage latency, causing the Manager to fence the SPM, and the operation to fail. Now, concurrent SPM operations are prioritized so that longer, high I/O operations do not starve more important tasks of resources. High latency in low priority operations no longer causes the SPM to be fenced.
Clone Of:
Environment:
Last Closed: 2012-12-04 19:09:59 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
## Logs vdsm, rhevm (733.62 KB, application/x-gzip)
2012-09-04 13:10 UTC, vvyazmin@redhat.com 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2012:1508 0 normal SHIPPED_LIVE Important: rhev-3.1.0 vdsm security, bug fix, and enhancement update 2012-12-04 23:48:05 UTC

Description vvyazmin@redhat.com 2012-09-04 13:10:22 UTC 
Created attachment 609675 [details]
## Logs vdsm, rhevm

Description of problem:
Unable to delete multiple virtual disks (with Wipe after delete option)

Version-Release number of selected component (if applicable):
RHEVM 3.1 - SI16

RHEVM: rhevm-3.1.0-14.el6ev.noarch
VDSM: vdsm-4.9.6-31.0.el6_3.x86_64
LIBVIRT: libvirt-0.9.10-21.el6_3.4.x86_64
QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.295.el6_3.1.x86_64
SANLOCK: sanlock-2.3-3.el6_3.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Create DC iSCSI with 2 hosts.
2. Create Storage Domain (Master) - SD-01
3. Create 4 virtual disks (all disks: Preallocated, Wipe after delete, Size = 5GB) on SD-01
4. Select all virtual disk (from previous step), and delete
5. Create a new 4 virtual disk, during deleting process
  
Actual results:
1. Failed delete all virtual disks
2. Engine fence SPM
3. Data Center is initialized
4. All SD in current DC, not responding

Expected results:
1. Prevent fencing SPM
2. Succeed delete all virtual disks
3. All SD up and running

Additional info:

Thread-34372::INFO::2012-09-04 13:28:46,608::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='af7e917f-8622-4e74-839c
Thread-34372::INFO::2012-09-04 13:28:47,424::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34387::INFO::2012-09-04 13:28:58,467::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='41ecb604-a1f8-4a6c-b80c
Thread-34387::INFO::2012-09-04 13:28:59,256::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34404::INFO::2012-09-04 13:29:14,684::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='8b7d5a76-c450-4163-bbc1
Thread-34404::INFO::2012-09-04 13:29:15,465::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34416::INFO::2012-09-04 13:29:25,905::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='c12d5fbb-14c1-4e5e-b0c8
Thread-34416::INFO::2012-09-04 13:29:26,694::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34454::INFO::2012-09-04 13:30:10,550::logUtils::37::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='41ecb604-a1f8-4a6c-b80c-
Thread-34454::INFO::2012-09-04 13:30:13,633::logUtils::39::dispatcher::(wrapper) Run and protect: deleteImage, Return response: None
Thread-34459::INFO::2012-09-04 13:30:13,917::logUtils::37::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='8b7d5a76-c450-4163-bbc1-
Thread-34459::INFO::2012-09-04 13:30:23,974::logUtils::39::dispatcher::(wrapper) Run and protect: deleteImage, Return response: None
Thread-34469::INFO::2012-09-04 13:30:24,502::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='3e000ee0-2a73-4016-bce0
Thread-34469::INFO::2012-09-04 13:31:07,175::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34496::INFO::2012-09-04 13:31:07,657::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='56ec984e-d535-470b-b6e4
Thread-34496::INFO::2012-09-04 13:31:37,659::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34515::INFO::2012-09-04 13:31:38,429::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='a2ac4720-fcd1-4d15-9502
Thread-34515::INFO::2012-09-04 13:32:25,275::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34545::INFO::2012-09-04 13:32:27,207::logUtils::37::dispatcher::(wrapper) Run and protect: createVolume(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='fa1345a5-8a55-4f7b-a39a
Thread-34545::INFO::2012-09-04 13:33:43,527::logUtils::39::dispatcher::(wrapper) Run and protect: createVolume, Return response: None
Thread-34603::INFO::2012-09-04 13:33:58,782::logUtils::37::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='c12d5fbb-14c1-4e5e-b0c8-
Thread-34603::INFO::2012-09-04 13:36:58,081::logUtils::39::dispatcher::(wrapper) Run and protect: deleteImage, Return response: None
Thread-34726::INFO::2012-09-04 13:37:19,987::logUtils::37::dispatcher::(wrapper) Run and protect: deleteImage(sdUUID='77635396-2c31-4c20-afb7-2e392f0d9c11', spUUID='b05558be-15b2-4aac-9fff-47752a45314b', imgUUID='af7e917f-8622-4e74-839c-
Thread-34726::INFO::2012-09-04 13:41:00,443::logUtils::39::dispatcher::(wrapper) Run and protect: deleteImage, Return response: None

/var/log/ovirt-engine/engine.log

2012-09-07 13:38:59,977 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (pool-4-thread-38) [64dc82cf] IrsBroker::Failed::DeleteImageGroupVDS due to: TimeoutException: 
2012-09-07 13:39:00,011 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (pool-4-thread-38) [64dc82cf] START, SpmStopVDSCommand(vdsId = dfba4214-f5f4-11e1-8bff-001a4a169738, storagePoolId = b05558be-15b2-4aac-9fff-4775
2a45314b), log id: aa85cb1
2012-09-07 13:39:00,048 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (pool-4-thread-38) [64dc82cf] FINISH, SpmStopVDSCommand, log id: aa85cb1
2012-09-07 13:39:00,048 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (pool-4-thread-38) [64dc82cf] IRS failover failed - cant allocate vds server
2012-09-07 13:39:00,048 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (pool-4-thread-38) [64dc82cf] FINISH, DeleteImageGroupVDSCommand, log id: 1d633b26
2012-09-07 13:39:00,068 INFO  [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (pool-4-thread-46) [32fdf2da] Running command: SetStoragePoolStatusCommand internal: true. Entities affected :  ID: b05558be-15b2-4aac-9fff-477
52a45314b Type: StoragePool
2012-09-07 13:39:00,098 ERROR [org.ovirt.engine.core.bll.RemoveImageCommand] (pool-4-thread-38) [64dc82cf] Command org.ovirt.engine.core.bll.RemoveImageCommand throw Vdc Bll exception. With error message VdcBLLException: java.lang.reflec
t.UndeclaredThrowableException
2012-09-07 13:39:00,151 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (pool-4-thread-46) [32fdf2da] hostFromVds::selectedVds - cougar05.scl.lab.tlv.redhat.com, spmStatus SPM, storage pool dC-iSCSI-01
2012-09-07 13:39:00,157 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (pool-4-thread-46) [32fdf2da] Initialize Irs proxy from vds: cougar05.scl.lab.tlv.redhat.com
2012-09-07 13:39:00,270 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (QuartzScheduler_Worker-56) START, SPMGetAllTasksInfoVDSCommand(storagePoolId = b05558be-15b2-4aac-9fff-47752a45314b, ignoreFailoverLi
mit = false, compatabilityVersion = null), log id: 4525942b

/var/log/vdsm/vdsm.log 

Thread-34726::ERROR::2012-09-04 13:41:03,015::SecureXMLRPCServer::73::root::(handle_error) client ('10.35.97.56', 42107)
Traceback (most recent call last):
  File "/usr/lib64/python2.6/SocketServer.py", line 560, in process_request_thread
    self.finish_request(request, client_address)
  File "/usr/lib64/python2.6/site-packages/vdsm/SecureXMLRPCServer.py", line 69, in finish_request
    client_address)
  File "/usr/lib64/python2.6/SocketServer.py", line 322, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib64/python2.6/SocketServer.py", line 617, in __init__
    self.handle()
  File "/usr/lib64/python2.6/BaseHTTPServer.py", line 329, in handle
    self.handle_one_request()
  File "/usr/lib64/python2.6/BaseHTTPServer.py", line 323, in handle_one_request
    method()
  File "/usr/lib64/python2.6/SimpleXMLRPCServer.py", line 490, in do_POST
    self.send_response(200)
  File "/usr/lib64/python2.6/BaseHTTPServer.py", line 385, in send_response
    self.send_header('Date', self.date_time_string())
  File "/usr/lib64/python2.6/BaseHTTPServer.py", line 390, in send_header
    self.wfile.write("%s: %s\r\n" % (keyword, value))
  File "/usr/lib64/python2.6/socket.py", line 324, in write
    self.flush()
  File "/usr/lib64/python2.6/socket.py", line 303, in flush
    self._sock.sendall(buffer(data, write_offset, buffer_size))
  File "/usr/lib64/python2.6/ssl.py", line 203, in sendall
    v = self.send(data[count:])
  File "/usr/lib64/python2.6/ssl.py", line 174, in send
    v = self._sslobj.write(data)
error: [Errno 32] Broken pipe
94eaf034-8ae4-4e8f-a1f4-baf10194fb94::DEBUG::2012-09-04 13:41:03,017::task::740::TaskManager.Task::(_save) Task=`94eaf034-8ae4-4e8f-a1f4-baf10194fb94`::_save: orig /rhev/data-center/b05558be-15b2-4aac-9fff-47752a45314b/mastersd/master/tasks/94eaf034-8ae4-4e8f-a1f4-baf10194fb94 temp /rhev/data-center/b05558be-15b2-4aac-9fff-47752a45314b/mastersd/master/tasks/94eaf034-8ae4-4e8f-a1f4-baf10194fb94.temp
Dummy-26784::DEBUG::2012-09-04 13:41:03,081::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.559274 s, 1.8 MB/s\n'; <rc> = 0
Comment 6 Greg Padgett 2012-09-21 21:22:20 UTC 
http://gerrit.ovirt.org/8121
Comment 7 Ayal Baron 2012-09-23 07:46:35 UTC 
As long as reduced priority doesn't starve these long running processes then I think it's better.
Comment 12 Greg Padgett 2012-10-22 13:12:56 UTC 
Change-Id: I1b3a9088ad550c6d235d22d00688673c2cac0f7e
Comment 15 vvyazmin@redhat.com 2012-10-24 13:00:03 UTC 
Verified on RHEVM 3.1 - SI22

RHEVM: rhevm-3.1.0-22.el6ev.noarch
VDSM: vdsm-4.9.6-39.0.el6_3.x86_64
LIBVIRT: libvirt-0.9.10-21.el6_3.5.x86_64
QEMU & KVM: qemu-kvm-rhev-0.12.1.2-2.295.el6_3.2.x86_64
SANLOCK: sanlock-2.3-4.el6_3.x86_64
Comment 17 errata-xmlrpc 2012-12-04 19:09:59 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2012-1508.html
Note You need to log in before you can comment on or make changes to this bug.