2:58 a.m.
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
3:05 a.m.
----- Original Message -----
From: "Sandro Bonazzola" <sbonazzo(a)redhat.com>
To: vdsm-devel(a)lists.fedorahosted.org
Cc: "Federico Simoncelli" <fsimonce(a)redhat.com>, "Alex Lourie"
<alourie(a)redhat.com>, "Moran Goldboim"
<mgoldboi(a)redhat.com>
Sent: Friday, June 7, 2013 9:58:46 AM
Subject: issue while creating data domain over NFS
Hi here is the relevant log in vdsm.log: vdsm is taken from master,
commit 419cafb
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'
My bad this is an issue I introduced recently. I didn't know that dd could
output such a human-friendly string. I thought I got it all covered, but I
didn't take in consideration the exponential notation (and your super-fast
storage domain :)
5.6832e-05
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',)
I'll get it fixed soon.
--
Federico
3:19 a.m.
Il 07/06/2013 10:05, Federico Simoncelli ha scritto:
----- Original Message -----
> From: "Sandro Bonazzola" <sbonazzo(a)redhat.com>
> To: vdsm-devel(a)lists.fedorahosted.org
> Cc: "Federico Simoncelli" <fsimonce(a)redhat.com>, "Alex
Lourie" <alourie(a)redhat.com>, "Moran Goldboim"
> <mgoldboi(a)redhat.com>
> Sent: Friday, June 7, 2013 9:58:46 AM
> Subject: issue while creating data domain over NFS
>
> Hi here is the relevant log in vdsm.log: vdsm is taken from master,
> commit 419cafb
>
> 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'
My bad this is an issue I introduced recently. I didn't know that dd could
output such a human-friendly string. I thought I got it all covered, but I
didn't take in consideration the exponential notation (and your super-fast
storage domain :)
5.6832e-05
> 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',)
I'll get it fixed soon.
Thanks!
--
Sandro Bonazzola
Better technology. Faster innovation. Powered by community collaboration.
See how it works at redhat.com
3:37 a.m.
----- Original Message -----
From: "Sandro Bonazzola" <sbonazzo(a)redhat.com>
To: "Federico Simoncelli" <fsimonce(a)redhat.com>
Cc: vdsm-devel(a)lists.fedorahosted.org, "Alex Lourie"
<alourie(a)redhat.com>, "Moran Goldboim" <mgoldboi(a)redhat.com>
Sent: Friday, June 7, 2013 10:19:55 AM
Subject: Re: issue while creating data domain over NFS
Il 07/06/2013 10:05, Federico Simoncelli ha scritto:
> ----- Original Message -----
>> From: "Sandro Bonazzola" <sbonazzo(a)redhat.com>
>> To: vdsm-devel(a)lists.fedorahosted.org
>> Cc: "Federico Simoncelli" <fsimonce(a)redhat.com>, "Alex
Lourie"
>> <alourie(a)redhat.com>, "Moran Goldboim"
>> <mgoldboi(a)redhat.com>
>> Sent: Friday, June 7, 2013 9:58:46 AM
>> Subject: issue while creating data domain over NFS
>>
>> Hi here is the relevant log in vdsm.log: vdsm is taken from master,
>> commit 419cafb
>>
>> 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'
> My bad this is an issue I introduced recently. I didn't know that dd could
> output such a human-friendly string. I thought I got it all covered, but I
> didn't take in consideration the exponential notation (and your super-fast
> storage domain :)
>
> 5.6832e-05
>
>> 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',)
> I'll get it fixed soon.
>
Thanks!
Can you verify that this is working?
http://gerrit.ovirt.org/15433
Make sure that your dd commands with "Storage.Misc.excCmd::(getReadDelay)"
prefix are still returning values in scientific notation.
Thanks,
--
Federico
4:21 a.m.
Il 07/06/2013 10:37, Federico Simoncelli ha scritto:
----- Original Message -----
> From: "Sandro Bonazzola" <sbonazzo(a)redhat.com>
> To: "Federico Simoncelli" <fsimonce(a)redhat.com>
> Cc: vdsm-devel(a)lists.fedorahosted.org, "Alex Lourie"
<alourie(a)redhat.com>, "Moran Goldboim" <mgoldboi(a)redhat.com>
> Sent: Friday, June 7, 2013 10:19:55 AM
> Subject: Re: issue while creating data domain over NFS
>
> Il 07/06/2013 10:05, Federico Simoncelli ha scritto:
>> ----- Original Message -----
>>> From: "Sandro Bonazzola" <sbonazzo(a)redhat.com>
>>> To: vdsm-devel(a)lists.fedorahosted.org
>>> Cc: "Federico Simoncelli" <fsimonce(a)redhat.com>, "Alex
Lourie"
>>> <alourie(a)redhat.com>, "Moran Goldboim"
>>> <mgoldboi(a)redhat.com>
>>> Sent: Friday, June 7, 2013 9:58:46 AM
>>> Subject: issue while creating data domain over NFS
>>>
>>> Hi here is the relevant log in vdsm.log: vdsm is taken from master,
>>> commit 419cafb
>>>
>>> 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'
>> My bad this is an issue I introduced recently. I didn't know that dd could
>> output such a human-friendly string. I thought I got it all covered, but I
>> didn't take in consideration the exponential notation (and your super-fast
>> storage domain :)
>>
>> 5.6832e-05
>>
>>> 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',)
>> I'll get it fixed soon.
>>
> Thanks!
Can you verify that this is working?
http://gerrit.ovirt.org/15433
Make sure that your dd commands with "Storage.Misc.excCmd::(getReadDelay)"
prefix are still returning values in scientific notation.
Thanks,
seems to work fine, thanks.
59fe9f79-c681-4980-b3b6-6006f1acf3a8::DEBUG::2013-06-07
11:14:20,917::task::974::TaskManager.Task::(_decref)
Task=`59fe9f79-c681-4980-b3b6-6006f1acf3a8`::ref 0 aborting False
59fe9f79-c681-4980-b3b6-6006f1acf3a8::DEBUG::2013-06-07
11:14:20,918::threadPool::57::Misc.ThreadPool::(setRunningTask) Number
of running tasks: 0
Thread-81::DEBUG::2013-06-07
11:14:22,179::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/192.168.1.104:_var_lib_images2/7627dea9-6906-4954-9ad4-091713d7b160/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-81::DEBUG::2013-06-07
11:14:22,184::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied,
0.000110129 s, 4.3 MB/s\n'; <rc> = 0
Thread-81::DEBUG::2013-06-07
11:14:32,200::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/192.168.1.104:_var_lib_images2/7627dea9-6906-4954-9ad4-091713d7b160/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-81::DEBUG::2013-06-07
11:14:32,204::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied,
9.7255e-05 s, 4.9 MB/s\n'; <rc> = 0
^^^^ this has scientific notation and not failed.
Thread-81::DEBUG::2013-06-07
11:14:42,217::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/192.168.1.104:_var_lib_images2/7627dea9-6906-4954-9ad4-091713d7b160/dom_md/metadata
bs=4096 count=1' (cwd None)
Thread-81::DEBUG::2013-06-07
11:14:42,223::fileSD::238::Storage.Misc.excCmd::(getReadDelay) SUCCESS:
<err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied,
0.000155976 s, 3.1 MB/s\n'; <rc> = 0
Thread-81::DEBUG::2013-06-07
11:14:52,237::fileSD::238::Storage.Misc.excCmd::(getReadDelay)
'/usr/bin/dd iflag=direct
if=/rhev/data-center/mnt/192.168.1.104:_var_lib_images2/7627dea9-6906-4954-9ad4-091713d7b160/dom_md/metadata
bs=4096 count=1' (cwd None)
--
Sandro Bonazzola
Better technology. Faster innovation. Powered by community collaboration.
See how it works at redhat.com
4032
days inactive
4032
days old
vdsm-devel@lists.fedorahosted.org
4 comments
2 participants
participants (2)
-
Federico Simoncelli -
Sandro Bonazzola