Bug 838547 - 3.1 - VDSM [Scalability]: 'OSError' during refreshStoragePool mkdir that fails over File exists.
3.1 - VDSM [Scalability]: 'OSError' during refreshStoragePool mkdir that fail...
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: vdsm (Show other bugs)
6.3
x86_64 Linux
medium Severity medium
: rc
: ---
Assigned To: Eduardo Warszawski
Haim
storage,scale
: ZStream
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-07-09 08:41 EDT by Omri Hochman
Modified: 2014-01-12 19:52 EST (History)
12 users (show)

See Also:
Fixed In Version: vdsm-4.9.6-41.0
Doc Type: Bug Fix
Doc Text:
Previously, when attempting to activate five or six storage domains at the same time, refreshStoragePool attempted to create a folder that already existed, which caused an "OSError [Errno 17]" to be thrown. This issue was caused by a race condition in fileUtils.createdir(). An updated version of VDSM now creates the target directory; if the target directory already exists, VDSM ensures that the directory has the correct permissions, and "OSError [Errno 17]" is not thrown.
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-12-04 14:02:18 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
full_vdsm)log (578.14 KB, application/octet-stream)
2012-07-09 08:43 EDT, Omri Hochman
no flags Details

  None (edit)
Description Omri Hochman 2012-07-09 08:41:15 EDT
VDSM: refreshStoragePool attempted to mkdir an exists folder and failed with 'OSError: [Errno 17] File exists:'.

Description: 
***********
I worked on scale environment with 40 hosts and 100 iSCSI Storage-Domains (EMC Machine), When attempted to activate several (5-6) Storage Domains at the same time, refreshStoragePool attempted to mkdir folder that was already exist It returned OSError [Errno 17].  

Note: 
*******
might be related - the SSL request of the refreshStoragePool command took long time (more than 4 minutes) it failed on timeout with "BrokenPipe" Error (same Thread-38098 at vdsm.log). 


VDSM.log
************
Thread-38098::ERROR::2012-07-09 08:35:34,901::task::853::TaskManager.Task::(_setError) Task=`43caf957-5dda-46e0-932e-6699ba021304`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 861, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 699, in refreshStoragePool
    pool.refresh(msdUUID, masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1178, in refresh
    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
  File "/usr/share/vdsm/storage/sp.py", line 1139, in __rebuild
    fileUtils.createdir(os.path.join(domaindir, sd.DOMAIN_META_DATA))
  File "/usr/share/vdsm/storage/fileUtils.py", line 149, in createdir
    os.makedirs(dirPath)
  File "/usr/lib64/python2.6/os.py", line 157, in makedirs
    mkdir(name, mode)
OSError: [Errno 17] File exists: '/rhev/data-center/mnt/blockSD/3191acd9-0fc6-4270-99b3-7775fa70ed15/dom_md'
', '35459266-07dd-4f15-92c1-f6e36e9b851a', 1) {} failed - stopping task
Thread-38098::DEBUG::2012-07-09 08:35:34,905::task::1199::TaskManager.Task::(stop) Task=`43caf957-5dda-46e0-932e-6699ba021304`::stopping in state preparing (force False)
Thread-38098::DEBUG::2012-07-09 08:35:34,905::task::978::TaskManager.Task::(_decref) Task=`43caf957-5dda-46e0-932e-6699ba021304`::ref 1 aborting True
Thread-38098::INFO::2012-07-09 08:35:34,906::task::1157::TaskManager.Task::(prepare) Task=`43caf957-5dda-46e0-932e-6699ba021304`::aborting: Task is aborted: u"[Errno 17] File exists: '/rhev/data-center/mnt/blockSD
/3191acd9-0fc6-4270-99b3-7775fa70ed15/dom_md'" - code 100
Thread-38098::DEBUG::2012-07-09 08:35:34,906::task::1162::TaskManager.Task::(prepare) Task=`43caf957-5dda-46e0-932e-6699ba021304`::Prepare: aborted: [Errno 17] File exists: '/rhev/data-center/mnt/blockSD/3191acd9-
0fc6-4270-99b3-7775fa70ed15/dom_md'
Thread-38098::DEBUG::2012-07-09 08:35:34,906::task::978::TaskManager.Task::(_decref) Task=`43caf957-5dda-46e0-932e-6699ba021304`::ref 0 aborting True
Thread-38098::DEBUG::2012-07-09 08:35:34,907::task::913::TaskManager.Task::(_doAbort) Task=`43caf957-5dda-46e0-932e-6699ba021304`::Task._doAbort: force False
Thread-38098::DEBUG::2012-07-09 08:35:34,907::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-38098::DEBUG::2012-07-09 08:35:34,907::task::588::TaskManager.Task::(_updateState) Task=`43caf957-5dda-46e0-932e-6699ba021304`::moving from state preparing -> state aborting
Thread-38098::DEBUG::2012-07-09 08:35:34,907::task::537::TaskManager.Task::(__state_aborting) Task=`43caf957-5dda-46e0-932e-6699ba021304`::_aborting: recover policy none
Thread-38098::DEBUG::2012-07-09 08:35:34,908::task::588::TaskManager.Task::(_updateState) Task=`43caf957-5dda-46e0-932e-6699ba021304`::moving from state aborting -> state failed
Thread-38098::DEBUG::2012-07-09 08:35:34,908::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.50d275f3-2029-4fd9-bc86-20333f3cb24f': < ResourceRef 'Storag
e.50d275f3-2029-4fd9-bc86-20333f3cb24f', isValid: 'True' obj: 'None'>}
Thread-38098::DEBUG::2012-07-09 08:35:34,908::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-38098::DEBUG::2012-07-09 08:35:34,909::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.50d275f3-2029-4fd9-bc86-20333f3cb24f'
Thread-38098::DEBUG::2012-07-09 08:35:34,909::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.50d275f3-2029-4fd9-bc86-20333f3cb24f' (0 active users)
Thread-38098::DEBUG::2012-07-09 08:35:34,909::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.50d275f3-2029-4fd9-bc86-20333f3cb24f' is free, finding out if anyone is waiting for it.
Thread-38098::DEBUG::2012-07-09 08:35:34,910::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.50d275f3-2029-4fd9-bc86-20333f3cb24f', Clearing records.
Thread-38098::ERROR::2012-07-09 08:35:34,910::dispatcher::69::Storage.Dispatcher.Protect::(run) [Errno 17] File exists: '/rhev/data-center/mnt/blockSD/3191acd9-0fc6-4270-99b3-7775fa70ed15/dom_md'
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/dispatcher.py", line 61, in run
    result = ctask.prepare(self.func, *args, **kwargs)
  File "/usr/share/vdsm/storage/task.py", line 1164, in prepare
    raise self.error
OSError: [Errno 17] File exists: '/rhev/data-center/mnt/blockSD/3191acd9-0fc6-4270-99b3-7775fa70ed15/dom_md'
Comment 1 Omri Hochman 2012-07-09 08:43:17 EDT
Created attachment 597067 [details]
full_vdsm)log
Comment 2 Eduardo Warszawski 2012-07-15 14:09:24 EDT
Brief of refreshStoragePoolTimes:

Thread-38055    2012-07-09 08:25:24,973         2012-07-09 08:35:31,909
Thread-38080    2012-07-09 08:26:08,145         2012-07-09 08:30:27,482
Thread-38098    2012-07-09 08:28:51,500         2012-07-09 08:35:34,910 Raise
Thread-38129    2012-07-09 08:29:59,013         2012-07-09 08:35:31,986
Comment 3 Eduardo Warszawski 2012-10-23 07:34:20 EDT
http://gerrit.ovirt.org/#/c/8732/2
Comment 6 Omri Hochman 2012-11-11 09:36:25 EST
Unable to reproduce vdsm-4.9.6-41.0.el6_3.x86_64 (rhevm build si24).
Comment 8 errata-xmlrpc 2012-12-04 14:02:18 EST
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.