Hi here is the relevant log in vdsm.log: vdsm is taken from master,
commit 419cafb
Thread-273::INFO::2013-06-07
09:49:24,305::logUtils::44::dispatcher::(wrapper) Run and protect:
createVolume(sdUUID='5569b4ce-c43b-434e-b0d2-7066a6e9489a',
spUUID='1fa7166d-ca70-4c02-acec-bd888aa8e5f9',
imgUUID='2fdbf1be-f028-492c-8741-a46789f8660a', size=41943040,
volFormat=5, preallocate=2, diskType=2,
volUUID='316faf9c-1780-4820-85bf-c886c3894a09', desc='Hosted Engine
Image', srcImgUUID='00000000-0000-0000-0000-000000000000',
srcVolUUID='00000000-0000-0000-0000-000000000000')
Thread-273::INFO::2013-06-07
09:49:24,305::fileSD::315::Storage.StorageDomain::(validate)
sdUUID=5569b4ce-c43b-434e-b0d2-7066a6e9489a
Thread-273::DEBUG::2013-06-07
09:49:24,316::persistentDict::234::Storage.PersistentDict::(refresh)
read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=local_storage',
'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30',
'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1',
'POOL_DESCRIPTION=local_datacenter',
'POOL_DOMAINS=5569b4ce-c43b-434e-b0d2-7066a6e9489a:Active',
'POOL_SPM_ID=1', 'POOL_SPM_LVER=0',
'POOL_UUID=1fa7166d-ca70-4c02-acec-bd888aa8e5f9',
'REMOTE_PATH=192.168.1.104:/var/lib/images2', 'ROLE=Master',
'SDUUID=5569b4ce-c43b-434e-b0d2-7066a6e9489a', 'TYPE=NFS', 'VERSION=3',
'_SHA_CKSUM=b6e962017a3320b970ca08ba64cc23cb2b663197']
Thread-273::DEBUG::2013-06-07
09:49:24,317::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`Storage.5569b4ce-c43b-434e-b0d2-7066a6e9489a`ReqID=`c52a859d-3d30-41d7-99cd-4ff8f3b5c98a`::Request
was made in '/usr/share/vdsm/storage/hsm.py' line '1404' at 'createVolume'
Thread-273::DEBUG::2013-06-07
09:49:24,318::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource
'Storage.5569b4ce-c43b-434e-b0d2-7066a6e9489a' for lock type 'shared'
Thread-273::DEBUG::2013-06-07
09:49:24,318::resourceManager::600::ResourceManager::(registerResource)
Resource 'Storage.5569b4ce-c43b-434e-b0d2-7066a6e9489a' is free. Now
locking as 'shared' (1 active user)
Thread-273::DEBUG::2013-06-07
09:49:24,318::resourceManager::237::ResourceManager.Request::(grant)
ResName=`Storage.5569b4ce-c43b-434e-b0d2-7066a6e9489a`ReqID=`c52a859d-3d30-41d7-99cd-4ff8f3b5c98a`::Granted
request
Thread-273::DEBUG::2013-06-07
09:49:24,319::task::811::TaskManager.Task::(resourceAcquired)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_resourcesAcquired:
Storage.5569b4ce-c43b-434e-b0d2-7066a6e9489a (shared)
Thread-273::DEBUG::2013-06-07
09:49:24,319::task::974::TaskManager.Task::(_decref)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::ref 1 aborting False
Thread-273::DEBUG::2013-06-07
09:49:24,335::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
Thread-273::DEBUG::2013-06-07
09:49:24,389::taskManager::68::TaskManager::(scheduleJob) scheduled job
createVolume for task 5ee704f3-4834-4413-8e5b-9e22852fac5b
Thread-273::INFO::2013-06-07
09:49:24,390::logUtils::47::dispatcher::(wrapper) Run and protect:
createVolume, Return response: None
Thread-273::DEBUG::2013-06-07
09:49:24,390::task::1163::TaskManager.Task::(prepare)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::Prepare: 1 jobs exist, move
to acquiring
Thread-273::DEBUG::2013-06-07
09:49:24,390::task::579::TaskManager.Task::(_updateState)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::moving from state preparing
-> state acquiring
Thread-273::DEBUG::2013-06-07
09:49:24,391::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
Thread-273::DEBUG::2013-06-07
09:49:24,488::task::579::TaskManager.Task::(_updateState)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::moving from state acquiring
-> state queued
Thread-273::DEBUG::2013-06-07
09:49:24,489::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
Thread-273::DEBUG::2013-06-07
09:49:24,573::taskManager::50::TaskManager::(_queueTask) queuing task:
5ee704f3-4834-4413-8e5b-9e22852fac5b
Thread-273::DEBUG::2013-06-07
09:49:24,574::taskManager::56::TaskManager::(_queueTask) task queued:
5ee704f3-4834-4413-8e5b-9e22852fac5b
72ab072f-e451-4a82-99b2-b85ef36aba04::DEBUG::2013-06-07
09:49:24,574::threadPool::57::Misc.ThreadPool::(setRunningTask) Number
of running tasks: 1
Thread-273::DEBUG::2013-06-07
09:49:24,576::task::1165::TaskManager.Task::(prepare)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::returning
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,576::threadPool::205::Misc.ThreadPool.WorkerThread::(run) Task:
5ee704f3-4834-4413-8e5b-9e22852fac5b running: <bound method Task.commit
of <storage.task.Task instance at 0x7f9334103ea8>> with: None
Thread-273::DEBUG::2013-06-07
09:49:24,578::task::974::TaskManager.Task::(_decref)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::ref 0 aborting False
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,579::task::1176::TaskManager.Task::(commit)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::committing task:
5ee704f3-4834-4413-8e5b-9e22852fac5b
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,581::task::579::TaskManager.Task::(_updateState)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::moving from state queued ->
state running
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,583::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,675::task::889::TaskManager.Task::(_runJobs)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::Task.run: running job 0:
createVolume: <bound method StoragePool.createVolume of
<storage.sp.StoragePool object at 0x2454dd0>> (args:
('5569b4ce-c43b-434e-b0d2-7066a6e9489a',
'2fdbf1be-f028-492c-8741-a46789f8660a', 41943040, 5, 2, 2,
'316faf9c-1780-4820-85bf-c886c3894a09', 'Hosted Engine Image',
'00000000-0000-0000-0000-000000000000',
'00000000-0000-0000-0000-000000000000') kwargs: {})
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,675::task::315::TaskManager.Task::(run)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::Job.run: running
createVolume: <bound method StoragePool.createVolume of
<storage.sp.StoragePool object at 0x2454dd0>> (args:
('5569b4ce-c43b-434e-b0d2-7066a6e9489a',
'2fdbf1be-f028-492c-8741-a46789f8660a', 41943040, 5, 2, 2,
'316faf9c-1780-4820-85bf-c886c3894a09', 'Hosted Engine Image',
'00000000-0000-0000-0000-000000000000',
'00000000-0000-0000-0000-000000000000') kwargs: {}) callback None
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,676::resourceManager::197::ResourceManager.Request::(__init__)
ResName=`5569b4ce-c43b-434e-b0d2-7066a6e9489a_imageNS.2fdbf1be-f028-492c-8741-a46789f8660a`ReqID=`ad9c6518-a498-4c53-b995-32ebdad2e934`::Request
was made in '/usr/share/vdsm/storage/sp.py' line '1973' at 'createVolume'
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,676::resourceManager::541::ResourceManager::(registerResource)
Trying to register resource
'5569b4ce-c43b-434e-b0d2-7066a6e9489a_imageNS.2fdbf1be-f028-492c-8741-a46789f8660a'
for lock type 'exclusive'
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,677::resourceFactories::125::Storage.ResourcesFactories::(__getResourceCandidatesList)
Image 2fdbf1be-f028-492c-8741-a46789f8660a does not exist in domain
5569b4ce-c43b-434e-b0d2-7066a6e9489a
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,677::resourceManager::600::ResourceManager::(registerResource)
Resource
'5569b4ce-c43b-434e-b0d2-7066a6e9489a_imageNS.2fdbf1be-f028-492c-8741-a46789f8660a'
is free. Now locking as 'exclusive' (1 active user)
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,677::resourceManager::237::ResourceManager.Request::(grant)
ResName=`5569b4ce-c43b-434e-b0d2-7066a6e9489a_imageNS.2fdbf1be-f028-492c-8741-a46789f8660a`ReqID=`ad9c6518-a498-4c53-b995-32ebdad2e934`::Granted
request
5ee704f3-4834-4413-8e5b-9e22852fac5b::INFO::2013-06-07
09:49:24,677::image::122::Storage.Image::(create) Create placeholder
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/5569b4ce-c43b-434e-b0d2-7066a6e9489a/images/2fdbf1be-f028-492c-8741-a46789f8660a
for image's volumes
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,678::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
5ee704f3-4834-4413-8e5b-9e22852fac5b::INFO::2013-06-07
09:49:24,831::volume::464::Storage.Volume::(create) Creating volume
316faf9c-1780-4820-85bf-c886c3894a09
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:24,832::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
5ee704f3-4834-4413-8e5b-9e22852fac5b::DEBUG::2013-06-07
09:49:31,268::task::736::TaskManager.Task::(_save)
Task=`5ee704f3-4834-4413-8e5b-9e22852fac5b`::_save: orig
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b
temp
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/mastersd/master/tasks/5ee704f3-4834-4413-8e5b-9e22852fac5b.temp
5ee704f3-4834-4413-8e5b-9e22852fac5b::INFO::2013-06-07
09:49:31,573::fileVolume::154::Storage.Volume::(_create) Request to
create RAW volume
/rhev/data-center/1fa7166d-ca70-4c02-acec-bd888aa8e5f9/5569b4ce-c43b-434e-b0d2-7066a6e9489a/images/2fdbf1be-f028-492c-8741-a46789f8660a/316faf9c-1780-4820-85bf-c886c3894a09
with size = 41943040 sectors
Thread-263::DEBUG::2013-06-07
09:49:44,063::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/192.168.1.104:_var_lib_images2/5569b4ce-c43b-434e-b0d2-7066a6e9489a/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-263::DEBUG::2013-06-07
09:49:44,068::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied,
5.6832e-05 s, 8.4 MB/s\n'; <rc> = 0
Thread-263::ERROR::2013-06-07
09:49:44,069::misc::240::Storage.Misc::(readspeed) Unable to parse dd
output: '479 bytes (479 B) copied, 5.6832e-05 s, 8.4 MB/s'
Thread-263::ERROR::2013-06-07
09:49:44,069::domainMonitor::225::Storage.DomainMonitorThread::(_monitorDomain)
Error while collecting domain 5569b4ce-c43b-434e-b0d2-7066a6e9489a
monitoring information
Traceback (most recent call last):
File "/usr/share/vdsm/storage/domainMonitor.py", line 203, in
_monitorDomain
self.nextStatus.readDelay = self.domain.getReadDelay()
File "/usr/share/vdsm/storage/fileSD.py", line 238, in getReadDelay
stats = misc.readspeed(self.metafile, 4096)
File "/usr/share/vdsm/storage/misc.py", line 241, in readspeed
raise se.MiscFileReadException(path)
MiscFileReadException: Internal file read failure:
('/rhev/data-center/mnt/192.168.1.104:_var_lib_images2/5569b4ce-c43b-434e-b0d2-7066a6e9489a/dom_md/metadata',)
Thread-263::DEBUG::2013-06-07
09:49:44,069::domainMonitor::233::Storage.DomainMonitorThread::(_monitorDomain)
Domain 5569b4ce-c43b-434e-b0d2-7066a6e9489a changed its status to Invalid
Thread-274::DEBUG::2013-06-07
09:49:44,070::misc::925::Event.Storage.DomainMonitor.onDomainConnectivityStateChange::(_emit)
Emitting event
Thread-274::DEBUG::2013-06-07
09:49:44,070::misc::935::Event.Storage.DomainMonitor.onDomainConnectivityStateChange::(_emit)
Calling registered method `_upgradePoolDomain`
Thread-274::DEBUG::2013-06-07
09:49:44,071::misc::945::Event.Storage.DomainMonitor.onDomainConnectivityStateChange::(_emit)
Event emitted
--
Sandro Bonazzola
Better technology. Faster innovation. Powered by community collaboration.
See how it works at redhat.com
_______________________________________________
vdsm-devel mailing list
vdsm-devel@lists.fedorahosted.org
https://lists.fedorahosted.org/mailman/listinfo/vdsm-devel
