Bug 854242

Summary: 3.1 - [vdsm] unable to delete multiple virtual disks with Wipe after delete (engine fence SPM)
Product: Red Hat Enterprise Linux 6 Reporter: vvyazmin <vvyazmin>
Component: vdsmAssignee: Greg Padgett <gpadgett>
Status: CLOSED ERRATA QA Contact: vvyazmin <vvyazmin>
Severity: high Docs Contact:
Priority: unspecified    
Version: 6.3CC: abaron, acathrow, amureini, bazulay, dyasny, hateya, iheim, ilvovsky, lpeer, Rhev-m-bugs, thildred, yeylon, ykaul
Target Milestone: rcKeywords: ZStream
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard: storage
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.
 Story Points: ---
Clone Of: Environment:
Last Closed: 2012-12-04 19:09:59 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
## Logs vdsm, rhevm none

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