Bug 845832

Summary: [Scalability] Attachment of storage domains to data center via rhevm-sdk sometimes fails
Product: Red Hat Enterprise Virtualization Manager Reporter: Rami Vaknin <rvaknin>
Component: ovirt-engine-restapiAssignee: Juan Hernández <juan.hernandez>
Status: CLOSED CURRENTRELEASE QA Contact: Rami Vaknin <rvaknin>
Severity: high Docs Contact:
Priority: unspecified    
Version: 3.1.0CC: abaron, dyasny, ecohen, hateya, iheim, juan.hernandez, mpastern, Rhev-m-bugs, sgrinber, yeylon, ykaul
Target Milestone: ---Keywords: TestBlocker
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: infra
Fixed In Version: si22 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-12-04 20:01:06 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 849442, 875709    
Bug Blocks: 853045    
Attachments:
Description Flags
engine.log
none
vdsm.log and server.log
none
engine_si13.3.log
none
engine.log none

Description Rami Vaknin 2012-08-05 13:26:16 UTC 
Created attachment 602359 [details]
engine.log

Version:
RHEVM - SI13
Client that runs the script - rhevm-sdk-3.1.0.4-1.el6ev.noarch

Scenario:
I run a sdk-based script that create-attach-activate 100 iscsi storage domains to data center, each storage domain consists of 1 lun, all luns from the same storage server.

Every time I run this script, it starts to fail on attaching the newly-created storage domains to the data center, it happens in the ~30th storage domain attachment.


I get:
send: 'POST /api/datacenters/7f8d8b1f-6881-4cbe-b4f1-ffd6f139b2b5/storagedomains HTTP/1.1\r\nHost: cougar01.scl.lab.tlv.redhat.com\r\nAccept-Encoding: identity\r\nContent-Length: 1448\r\ncookie: JSESSIONID=8HvmCCcevO3VFOw9qwdBESwc\r\nPrefer: persistent-auth\r\nContent-type: application/xml\r\nAuthorization: Basic YWRtaW5AaW50ZXJuYWw6MTIzNDU2\r\n\r\n'
send: '<storage_domain href="/api/storagedomains/387e9b92-22e2-4850-94cf-6825687c278c" id="387e9b92-22e2-4850-94cf-6825687c278c">\n    <name>3600601601282300036f94e5b78cbe111</name>\n    <link href="/api/storagedomains/387e9b92-22e2-4850-94cf-6825687c278c/permissions" rel="permissions"/>\n    <type>data</type>\n    <status>\n        <state>unattached</state>\n    </status>\n    <master>false</master>\n    <storage>\n        <type>iscsi</type>\n        <volume_group id="27LnOp-K3pn-4e9s-LRQI-lcRt-xXpF-Cf7olK">\n            <logical_unit id="3600601601282300036f94e5b78cbe111">\n                <address>10.35.160.107</address>\n                <port>3260</port>\n                <target>iqn.1992-04.com.emc:cx.ckm00121000438.b7</target>\n                <serial>SDGC_VRAID_CKM00121000438</serial>\n                <vendor_id>DGC</vendor_id>\n                <product_id>VRAID</product_id>\n                <lun_mapping>7</lun_mapping>\n                <portal>10.35.160.107:3260,4</portal>\n                <size>107374182400</size>\n                <paths>0</paths>\n                <volume_group_id>27LnOp-K3pn-4e9s-LRQI-lcRt-xXpF-Cf7olK</volume_group_id>\n                <storage_domain_id>387e9b92-22e2-4850-94cf-6825687c278c</storage_domain_id>\n            </logical_unit>\n        </volume_group>\n    </storage>\n    <available>102005473280</available>\n    <used>4294967296</used>\n    <committed>0</committed>\n    <storage_format>v3</storage_format>\n</storage_domain>\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Date: Sun, 05 Aug 2012 14:57:00 GMT
header: Content-Length: 655
header: Connection: close
header: Content-Type: text/html; charset=iso-8859-1
Failed to attach Storage Domain '3600601601282300036f94e5b78cbe111' to Data Center 'iscsi_dc', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 155, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1036, in add
    body=ParseHelper.toXml(storagedomain))
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/errors.py", line 98, in __init__
    f_detail = params.parseString(res)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 19340, in parseString
    doc = parsexml_(StringIO(inString))
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 73, in parsexml_
    doc = etree_.parse(*args, **kwargs)
  File "lxml.etree.pyx", line 2692, in lxml.etree.parse (src/lxml/lxml.etree.c:49594)
  File "parser.pxi", line 1517, in lxml.etree._parseDocument (src/lxml/lxml.etree.c:71540)
  File "parser.pxi", line 1545, in lxml.etree._parseMemoryDocument (src/lxml/lxml.etree.c:71812)
  File "parser.pxi", line 1424, in lxml.etree._parseDoc (src/lxml/lxml.etree.c:70673)
  File "parser.pxi", line 938, in lxml.etree._BaseParser._parseDoc (src/lxml/lxml.etree.c:67442)
  File "parser.pxi", line 539, in lxml.etree._ParserContext._handleParseResultDoc (src/lxml/lxml.etree.c:63824)
  File "parser.pxi", line 625, in lxml.etree._handleParseResult (src/lxml/lxml.etree.c:64745)
  File "parser.pxi", line 565, in lxml.etree._raiseParseError (src/lxml/lxml.etree.c:64088)
XMLSyntaxError: Space required after the Public Identifier, line 1, column 47
Comment 1 Yaniv Kaul 2012-08-05 18:31:28 UTC 
You have some of those in the log:
CanDoAction of action ActivateStorageDomain failed. Reasons:VAR__TYPE__STORAGE__DOMAIN,VAR__ACTION__ACTIVATE,ACTION_TYPE_FAILED_STORAGE_DOMAIN_STATUS_ILLEGAL

please attach VDSM log (and I'd also attach server.log, just in case).
Lastly, I don't see why it's an API bug and not a backend bug.
Comment 3 Rami Vaknin 2012-08-05 19:40:44 UTC 
(In reply to comment #1)
> You have some of those in the log:
> CanDoAction of action ActivateStorageDomain failed.
> Reasons:VAR__TYPE__STORAGE__DOMAIN,VAR__ACTION__ACTIVATE,
> ACTION_TYPE_FAILED_STORAGE_DOMAIN_STATUS_ILLEGAL

You get these errors since it's impossible to activate unattached storage domain - the script doesn't stop his cycle (create-attach-activate) in case of failure, I probably will change that.

> 
> please attach VDSM log (and I'd also attach server.log, just in case).

I'll look for the logs and attach them.

> Lastly, I don't see why it's an API bug and not a backend bug.

Since there is no error for backend about a problem, not even a General Failure, only parsing of POST Response (missing space char).

In addition, mpastern took a look at the debug and said it's an API bug.
Comment 4 Rami Vaknin 2012-08-05 19:47:22 UTC 
Created attachment 602383 [details]
vdsm.log and server.log
Comment 9 Michael Pasternak 2012-08-08 13:19:58 UTC 
rami, i suspect this is race between produced BE entity and api get() callback,
to verify this please re-run your tests using latest sdk and passing expect header

i.e .add(storagedomain, expect='201-created')

this will block /attach/ till it finished
Comment 10 Itamar Heim 2012-08-13 19:36:03 UTC 
before re-running these tests, i'd verify with daniel erez a set of his patches on valdiating storage domain attach per format level is merged.
Comment 11 Rami Vaknin 2012-08-14 14:28:32 UTC 
(In reply to comment #10)
> before re-running these tests, i'd verify with daniel erez a set of his
> patches on valdiating storage domain attach per format level is merged.

I don't have steps that fail on format validation, I'm attaching only v3 format SDs to 3.1 Data Center.
Comment 12 Rami Vaknin 2012-08-14 14:30:46 UTC 
We reproduced it on SI13.3 while adding sleep of 30 seconds between the storage creation and the storage attachement to data center in order to reduce the chances that it's a race.

Now it reproduced on the first storage domain attachement:

Connecting to engine core...  [OK]
Looking for available Host for Storage Domain Creation in Data Center 'iscsi_dc'...  Found Host 'puma05' in Data Center 'iscsi_dc'
Going to create a Master Storage Domain
Creating Storage Domain '3600601601282300067066d6e78cbe111'.. Storage Domain '3600601601282300067066d6e78cbe111' created successfully
Going to sleep for 30 seconds (master storage domain)
Attaching Storage Domain '3600601601282300067066d6e78cbe111' to Data Center 'iscsi_dc'..  Failed to attach Storage Domain '3600601601282300067066d6e78cbe111' to Data Center 'iscsi_dc', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1036, in add
    body=ParseHelper.toXml(storagedomain))
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/errors.py", line 98, in __init__
    f_detail = params.parseString(res)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 19340, in parseString
    doc = parsexml_(StringIO(inString))
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 73, in parsexml_
    doc = etree_.parse(*args, **kwargs)
  File "lxml.etree.pyx", line 2692, in lxml.etree.parse (src/lxml/lxml.etree.c:49594)
  File "parser.pxi", line 1517, in lxml.etree._parseDocument (src/lxml/lxml.etree.c:71540)
  File "parser.pxi", line 1545, in lxml.etree._parseMemoryDocument (src/lxml/lxml.etree.c:71812)
  File "parser.pxi", line 1424, in lxml.etree._parseDoc (src/lxml/lxml.etree.c:70673)
  File "parser.pxi", line 938, in lxml.etree._BaseParser._parseDoc (src/lxml/lxml.etree.c:67442)
  File "parser.pxi", line 539, in lxml.etree._ParserContext._handleParseResultDoc (src/lxml/lxml.etree.c:63824)
  File "parser.pxi", line 625, in lxml.etree._handleParseResult (src/lxml/lxml.etree.c:64745)
  File "parser.pxi", line 565, in lxml.etree._raiseParseError (src/lxml/lxml.etree.c:64088)
XMLSyntaxError: Space required after the Public Identifier, line 1, column 47
Comment 13 Omri Hochman 2012-08-14 14:45:11 UTC 
Created attachment 604323 [details]
engine_si13.3.log

(In reply to comment #12)
adding (si13.3) engine.log
Comment 15 Rami Vaknin 2012-08-15 11:28:39 UTC 
I ran it with the latest sdk (rhevm-sdk-3.1.0.5-1.el6ev.noarch) and with expect='201-created' in the add operaion, now the add operation fails with the same exception that was in the attach failure:

Connecting to engine core...  [OK]
Looking for available Host for Storage Domain Creation in Data Center 'iscsi_dc'...  Found Host 'puma04' in Data Center 'iscsi_dc'
Going to create a Master Storage Domain
Creating Storage Domain '36006016012823000370a06b7dae6e111'..  Failed to create Storage Domain '36006016012823000370a06b7dae6e111', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 138, in create
    self.getSdkProxy().storagedomains.add( self.getSdParams() , expect='201-created')
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 3837, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/errors.py", line 98, in __init__
    f_detail = params.parseString(res)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 19383, in parseString
    doc = parsexml_(StringIO(inString))
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 66, in parsexml_
    doc = etree_.parse(*args, **kwargs)
  File "lxml.etree.pyx", line 2692, in lxml.etree.parse (src/lxml/lxml.etree.c:49594)
  File "parser.pxi", line 1517, in lxml.etree._parseDocument (src/lxml/lxml.etree.c:71540)
  File "parser.pxi", line 1545, in lxml.etree._parseMemoryDocument (src/lxml/lxml.etree.c:71812)
  File "parser.pxi", line 1424, in lxml.etree._parseDoc (src/lxml/lxml.etree.c:70673)
  File "parser.pxi", line 938, in lxml.etree._BaseParser._parseDoc (src/lxml/lxml.etree.c:67442)
  File "parser.pxi", line 539, in lxml.etree._ParserContext._handleParseResultDoc (src/lxml/lxml.etree.c:63824)
  File "parser.pxi", line 625, in lxml.etree._handleParseResult (src/lxml/lxml.etree.c:64745)
  File "parser.pxi", line 565, in lxml.etree._raiseParseError (src/lxml/lxml.etree.c:64088)
XMLSyntaxError: Space required after the Public Identifier, line 1, column 47
Comment 16 Michael Pasternak 2012-08-15 12:15:00 UTC 
sounds like some kind of server issue, can you pls. check this using restapi?
(i'd like to see the output of failed CREATE), also please attach logs.
Comment 17 Rami Vaknin 2012-08-15 12:51:35 UTC 
Looks like an SDK bug.

I ran it again - first time with rhevm-sdk and second time with restapi using the same debug request of the rhevm-sdk trial.

In rhevm-sdk the storage domain creation failed while it succeded vim the restapi while using the same request.

REQUEST
=======

<storage_domain>
 <name>360060160128230002ee345b0dae6e111</name>
 <data_center href="/api/datacenters/1ff780be-0efc-4061-ba79-b7d169ce5b17" id="1ff780be-0efc-4061-ba79-b7d169ce5b17">
 <name>iscsi_dc</name>
<link href="/api/datacenters/1ff780be-0efc-4061-ba79-b7d169ce5b17/storagedomains" rel="storagedomains"/>
<link href="/api/datacenters/1ff780be-0efc-4061-ba79-b7d169ce5b17/permissions" rel="permissions"/>
<link href="/api/datacenters/1ff780be-0efc-4061-ba79-b7d169ce5b17/quotas" rel="quotas"/>
 <storage_type>iscsi</storage_type>
 <storage_format>v3</storage_format>
        <version major="3" minor="1"/>
<supported_versions>
<version major="3" minor="1"/>
</supported_versions>
 <status>
<state>up</state>
 </status>
    </data_center>
<type>data</type>
    <storage>
 <type>iscsi</type>
 <volume_group>
            <logical_unit id="360060160128230002ee345b0dae6e111">
 <address>10.35.160.107</address>
 <port>3260</port>
 <target>iqn.1992-04.com.emc:cx.ckm00121000438.b7</target>
 </logical_unit>
        </volume_group>
 </storage>
    <host href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78" id="c7c208ba-e6bb-11e1-b03d-002564b27d78">
 <name>puma04</name>
 <actions>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/deactivate" rel="deactivate"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/approve" rel="approve"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/iscsilogin" rel="iscsilogin"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/iscsidiscover" rel="iscsidiscover"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/commitnetconfig" rel="commitnetconfig"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/fence" rel="fence"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/install" rel="install"/>
            <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/activate" rel="activate"/>
        </actions>
        <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/storage" rel="storage"/>
        <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/nics" rel="nics"/>
        <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/tags" rel="tags"/>
        <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/permissions" rel="permissions"/>
        <link href="/api/hosts/c7c208ba-e6bb-11e1-b03d-002564b27d78/statistics" rel="statistics"/>
 <address>puma04.scl.lab.tlv.redhat.com</address>
 <certificate>
 <organization>redhat</organization>
 <subject>O=redhat,CN=puma04.scl.lab.tlv.redhat.com</subject>
 </certificate>
        <status>
 <state>up</state>
        </status>
 <cluster href="/api/clusters/0eacab64-e6bb-11e1-8c02-002564b27d78" id="0eacab64-e6bb-11e1-8c02-002564b27d78"/>
 <port>54321</port>
 <type>rhel</type>
        <storage_manager priority="5">false</storage_manager>
 <power_management type="ipmilan">
 <enabled>true</enabled>
 <address>puma04-mgmt.scl.lab.tlv.redhat.com</address>
 <username>admin</username>
 <options/>
        </power_management>
 <ksm>
 <enabled>false</enabled>
        </ksm>
 <transparent_hugepages>
 <enabled>true</enabled>
 </transparent_hugepages>
        <iscsi>
 <initiator>iqn.1994-05.com.redhat:eb51a4c81c9</initiator>
 </iscsi>
        <cpu>
            <topology cores="6" sockets="1"/>
            <name>Intel(R) Xeon(R) CPU           E5645  @ 2.40GHz</name>
 <speed>2400.000000</speed>
 </cpu>
 <memory>33658241024</memory>
 <summary>
 <active>0</active>
 <migrating>0</migrating>
 <total>0</total>
        </summary>
 </host>
 <storage_format>v3</storage_format>
</storage_domain>



From engine.log
===============



2012-08-15 15:37:05,149 INFO  [org.ovirt.engine.core.bll.storage.AddSANStorageDomainCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] Running command: AddSANStorageDomainCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: System
2012-08-15 15:37:05,175 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] START, CreateVGVDSCommand(vdsId = c7c208ba-e6bb-11e1-b03d-002564b27d78, storageDomainId=d4403782-f817-4e9c-9cc0-e67757574053, deviceList=[360060160128230002ee345b0dae6e111], force=false), log id: 65cb0088
2012-08-15 15:37:18,855 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] FINISH, CreateVGVDSCommand, return: nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd, log id: 65cb0088
2012-08-15 15:37:18,864 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] START, CreateStorageDomainVDSCommand(vdsId = c7c208ba-e6bb-11e1-b03d-002564b27d78, storageDomain=org.ovirt.engine.core.common.businessentities.storage_domain_static@e3ba867b, args=nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd), log id: 2e89002a
2012-08-15 15:38:09,745 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] FINISH, CreateStorageDomainVDSCommand, log id: 2e89002a
2012-08-15 15:38:09,761 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetStorageDomainStatsVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] START, GetStorageDomainStatsVDSCommand(vdsId = c7c208ba-e6bb-11e1-b03d-002564b27d78, storageDomainId=d4403782-f817-4e9c-9cc0-e67757574053), log id: 2e77ede0
2012-08-15 15:38:11,916 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetStorageDomainStatsVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] FINISH, GetStorageDomainStatsVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage_domains@1385b4f7, log id: 2e77ede0
2012-08-15 15:38:11,940 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVGInfoVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] START, GetVGInfoVDSCommand(vdsId = c7c208ba-e6bb-11e1-b03d-002564b27d78, VGID=nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd), log id: 38a5c21e
2012-08-15 15:38:12,023 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVGInfoVDSCommand] (ajp-/127.0.0.1:8009-9) [1c0f1830] FINISH, GetVGInfoVDSCommand, return: [org.ovirt.engine.core.common.businessentities.LUNs@4b80b8e], log id: 38a5c21e


RESPONSE
========

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<storage_domain href="/api/storagedomains/d4403782-f817-4e9c-9cc0-e67757574053" id="d4403782-f817-4e9c-9cc0-e67757574053">
    <name>360060160128230002ee345b0dae6e111</name>
    <link href="/api/storagedomains/d4403782-f817-4e9c-9cc0-e67757574053/permissions" rel="permissions"/>
    <type>data</type>
    <status>
        <state>unknown</state>
    </status>
    <master>false</master>
    <storage>
        <type>iscsi</type>
        <volume_group id="nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd">
            <logical_unit id="360060160128230002ee345b0dae6e111">
                <address>10.35.160.107</address>
                <port>3260</port>
                <target>iqn.1992-04.com.emc:cx.ckm00121000438.b7</target>
                <serial>SDGC_VRAID_CKM00121000438</serial>
                <vendor_id>DGC</vendor_id>
                <product_id>VRAID</product_id>
                <lun_mapping>11</lun_mapping>
                <portal>10.35.160.107:3260,4</portal>
                <size>322122547200</size>
                <paths>0</paths>
                <volume_group_id>nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd</volume_group_id>
                <storage_domain_id>d4403782-f817-4e9c-9cc0-e67757574053</storage_domain_id>
            </logical_unit>
            <logical_unit id="360060160128230002ee345b0dae6e111">
                <address>10.35.160.104</address>
                <port>3260</port>
                <target>iqn.1992-04.com.emc:cx.ckm00121000438.a6</target>
                <serial>SDGC_VRAID_CKM00121000438</serial>
                <vendor_id>DGC</vendor_id>
                <product_id>VRAID</product_id>
                <lun_mapping>11</lun_mapping>
                <portal>10.35.160.104:3260,1</portal>
                <size>322122547200</size>
                <paths>0</paths>
                <volume_group_id>nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd</volume_group_id>
                <storage_domain_id>d4403782-f817-4e9c-9cc0-e67757574053</storage_domain_id>
            </logical_unit>
            <logical_unit id="360060160128230002ee345b0dae6e111">
                <address>10.35.160.105</address>
                <port>3260</port>
                <target>iqn.1992-04.com.emc:cx.ckm00121000438.a7</target>
                <serial>SDGC_VRAID_CKM00121000438</serial>
                <vendor_id>DGC</vendor_id>
                <product_id>VRAID</product_id>
                <lun_mapping>11</lun_mapping>
                <portal>10.35.160.105:3260,2</portal>
                <size>322122547200</size>
                <paths>0</paths>
                <volume_group_id>nc1AaM-jVtq-WICT-yx0B-7PKp-wx2T-IkXFpd</volume_group_id>
                <storage_domain_id>d4403782-f817-4e9c-9cc0-e67757574053</storage_domain_id>
            </logical_unit>
        </volume_group>
    </storage>
    <available>316753838080</available>
    <used>4294967296</used>
    <committed>0</committed>
    <storage_format>v3</storage_format>
</storage_domain>
Comment 18 Rami Vaknin 2012-08-15 13:23:03 UTC 
I ran the same request in restapi, this time with the Expect header, the response below.

The bug is that you try to parse this response with xml parser although it has a problem of missing space after public identifier.
The public identifier here is:
"-//IETF//DTD HTML 2.0//EN"
and there is missing space after it, so the xml parser fails.


The response:
=============

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>500 Internal Server Error</title>
</head><body>
<h1>Internal Server Error</h1>
<p>The server encountered an internal error or
misconfiguration and was unable to complete
your request.</p>
<p>Please contact the server administrator,
 root@localhost and inform them of the time the error occurred,
and anything you might have done that may have
caused the error.</p>
<p>More information about this error may be available
in the server error log.</p>
<hr>
<address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at cougar01.scl.lab.tlv.redhat.com Port 80</address>
</body></html>
Comment 19 Michael Pasternak 2012-08-15 13:37:29 UTC 
(In reply to comment #18)
> I ran the same request in restapi, this time with the Expect header, the
> response below.

i don't get it, you saying that it succeeded in restapi, but in response below,
it has failed ?!, i assume this is sdk response...

> 
> The bug is that you try to parse this response with xml parser although it
> has a problem of missing space after public identifier.
> The public identifier here is:
> "-//IETF//DTD HTML 2.0//EN"
> and there is missing space after it, so the xml parser fails.
> 

problem here is that failure comes from the web server itself
and not from our app (restapi), also this responce doesn't have http spec params (http response code, etc.) and as result not properly handled,
sdk bug - i guess no, but sdk still have to be able handling this response.

> 
> The response:
> =============
> 
> <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
> <html><head>
> <title>500 Internal Server Error</title>
> </head><body>
> <h1>Internal Server Error</h1>
> <p>The server encountered an internal error or
> misconfiguration and was unable to complete
> your request.</p>
> <p>Please contact the server administrator,
>  root@localhost and inform them of the time the error occurred,
> and anything you might have done that may have
> caused the error.</p>
> <p>More information about this error may be available
> in the server error log.</p>
> <hr>
> <address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at
> cougar01.scl.lab.tlv.redhat.com Port 80</address>
> </body></html>

please copy/paste sdk code and server details, i'll check
Comment 20 Rami Vaknin 2012-08-15 14:28:23 UTC 
(In reply to comment #19)
> (In reply to comment #18)
> > I ran the same request in restapi, this time with the Expect header, the
> > response below.
> 
> i don't get it, you saying that it succeeded in restapi, but in response
> below,
> it has failed ?!, i assume this is sdk response...

I'll explain:

sdk: attachement of SD - fail (original scenario)

sdk: adding SD - pass
sdk with expect header: adding SD - fail

restapi: adding SD - pass
restapi with expect header: adding SD - fail

This is not the sdk response, it's the restapi response.
You can't get this response's body in sdk even in debug=True since you first pass it through the xml parser instead of printing it out (bug?).

> 
> > 
> > The bug is that you try to parse this response with xml parser although it
> > has a problem of missing space after public identifier.
> > The public identifier here is:
> > "-//IETF//DTD HTML 2.0//EN"
> > and there is missing space after it, so the xml parser fails.
> > 
> 
> problem here is that failure comes from the web server itself

Agree, you're right.

> and not from our app (restapi), also this responce doesn't have http spec
> params (http response code, etc.) and as result not properly handled,

It has, look at the debug in the bug's description:

reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Date: Sun, 05 Aug 2012 14:57:00 GMT
header: Content-Length: 655
header: Connection: close
header: Content-Type: text/html; charset=iso-8859-1

It's right that this error response is not properly handled (bug?)

> sdk bug - i guess no, but sdk still have to be able handling this response.

Agree.

> 
> > 
> > The response:
> > =============
> > 
> > <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
> > <html><head>
> > <title>500 Internal Server Error</title>
> > </head><body>
> > <h1>Internal Server Error</h1>
> > <p>The server encountered an internal error or
> > misconfiguration and was unable to complete
> > your request.</p>
> > <p>Please contact the server administrator,
> >  root@localhost and inform them of the time the error occurred,
> > and anything you might have done that may have
> > caused the error.</p>
> > <p>More information about this error may be available
> > in the server error log.</p>
> > <hr>
> > <address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at
> > cougar01.scl.lab.tlv.redhat.com Port 80</address>
> > </body></html>
> 
> please copy/paste sdk code and server details, i'll check

Code for reproduction:
======================

from storageIscsi import StorageIscsi
from libs import *
import constants as c

FILE='/root/scale_scripts/sdk/300g_list'
TARGET='iqn.1992-04.com.emc:cx.ckm00121000438.b7'
ADDRESS='10.35.160.107'
DC_NAME='iscsi_dc'

for lun_guid in getListOfStringsFromFileLines(FILE):
    iscsi_obj = StorageIscsi( name=lun_guid,
                              datacenter=DC_NAME,
                              storage_address=ADDRESS,
                              lun_guid = lun_guid,
                              target = TARGET )

    iscsi_obj.createAttachActivate()

=======================
You need to run this code from the 'sdk' directory of:
git://git.engineering.redhat.com/users/rvaknin/scale_scripts.git
Comment 21 Rami Vaknin 2012-08-15 14:30:09 UTC 
forgot to mention:
rhevm: http://cougar01.scl.lab.tlv.redhat.com
deactivate, detach and delete the storage domain before you re-run this script.
Comment 22 Michael Pasternak 2012-08-15 15:05:07 UTC 
(In reply to comment #20)
> (In reply to comment #19)
> > (In reply to comment #18)
> > > I ran the same request in restapi, this time with the Expect header, the
> > > response below.
> > 
> > i don't get it, you saying that it succeeded in restapi, but in response
> > below,
> > it has failed ?!, i assume this is sdk response...
> 
> I'll explain:
> 
> sdk: attachement of SD - fail (original scenario)
> 
> sdk: adding SD - pass
> sdk with expect header: adding SD - fail
> 
> restapi: adding SD - pass
> restapi with expect header: adding SD - fail

adding SD with expect header fails on both sdk/api - i.e server bug.

> 
> This is not the sdk response, it's the restapi response.
> You can't get this response's body in sdk even in debug=True since you first
> pass it through the xml parser instead of printing it out (bug?).

it wouldn't get to this code, if server response would contain http status,
from sdk POV request succeeded and response body contains SD (which is should be parsed)

> 
> > 
> > > 
> > > The bug is that you try to parse this response with xml parser although it
> > > has a problem of missing space after public identifier.
> > > The public identifier here is:
> > > "-//IETF//DTD HTML 2.0//EN"
> > > and there is missing space after it, so the xml parser fails.
> > > 
> > 
> > problem here is that failure comes from the web server itself
> 
> Agree, you're right.
> 
> > and not from our app (restapi), also this responce doesn't have http spec
> > params (http response code, etc.) and as result not properly handled,
> 
> It has, look at the debug in the bug's description:

it's not http status, but reply body str.

> 
> reply: 'HTTP/1.1 500 Internal Server Error\r\n'
> header: Date: Sun, 05 Aug 2012 14:57:00 GMT
> header: Content-Length: 655
> header: Connection: close
> header: Content-Type: text/html; charset=iso-8859-1
> 
> It's right that this error response is not properly handled (bug?)

no, explained above.

> 
> > sdk bug - i guess no, but sdk still have to be able handling this response.
> 
> Agree.
> 
> > 
> > > 
> > > The response:
> > > =============
> > > 
> > > <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
> > > <html><head>
> > > <title>500 Internal Server Error</title>
> > > </head><body>
> > > <h1>Internal Server Error</h1>
> > > <p>The server encountered an internal error or
> > > misconfiguration and was unable to complete
> > > your request.</p>
> > > <p>Please contact the server administrator,
> > >  root@localhost and inform them of the time the error occurred,
> > > and anything you might have done that may have
> > > caused the error.</p>
> > > <p>More information about this error may be available
> > > in the server error log.</p>
> > > <hr>
> > > <address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at
> > > cougar01.scl.lab.tlv.redhat.com Port 80</address>
> > > </body></html>
> > 
> > please copy/paste sdk code and server details, i'll check
> 
> Code for reproduction:
> ======================
> 
> from storageIscsi import StorageIscsi
> from libs import *
> import constants as c
> 
> FILE='/root/scale_scripts/sdk/300g_list'
> TARGET='iqn.1992-04.com.emc:cx.ckm00121000438.b7'
> ADDRESS='10.35.160.107'
> DC_NAME='iscsi_dc'
> 
> for lun_guid in getListOfStringsFromFileLines(FILE):
>     iscsi_obj = StorageIscsi( name=lun_guid,
>                               datacenter=DC_NAME,
>                               storage_address=ADDRESS,
>                               lun_guid = lun_guid,
>                               target = TARGET )
> 
>     iscsi_obj.createAttachActivate()
> 
> =======================
> You need to run this code from the 'sdk' directory of:
> git://git.engineering.redhat.com/users/rvaknin/scale_scripts.git
Comment 23 Michael Pasternak 2012-08-19 08:28:32 UTC 
> > sdk: adding SD - pass
> > sdk with expect header: adding SD - fail
> > 
> > restapi: adding SD - pass
> > restapi with expect header: adding SD - fail

sorry, i cannot reproduce this, need a step-by-step reproducer.
Comment 25 Michael Pasternak 2012-08-19 09:16:12 UTC 
ok, i see the problem (works on upstream env.), however this is not 500
WS error you posted in Comment 18, 

1. did you changed any Apache conf.?
2. can you add entire xml request you used in Comment 18 (inc. headers)?

<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>417 Expectation Failed</title>
</head><body>
<h1>Expectation Failed</h1>
<p>The expectation given in the Expect request-header
field could not be met by this server.
The client sent<pre>
    Expect: 201-created
</pre>
</p><p>Only the 100-continue expectation is supported.</p>
<hr>
<address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at cougar01.scl.lab.tlv.redhat.com Port 80</address>
</body></html>
Comment 26 Rami Vaknin 2012-08-19 09:19:47 UTC 
(In reply to comment #25)
> ok, i see the problem (works on upstream env.), however this is not 500
> WS error you posted in Comment 18, 

I provided you with my env + reporoducting scripts, do you need anything else?
> 
> 1. did you changed any Apache conf.?

No

> 2. can you add entire xml request you used in Comment 18 (inc. headers)?

No, only the body. the expect header I added in the needed box in Poster plugin.

> 
> <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
> <html><head>
> <title>417 Expectation Failed</title>
> </head><body>
> <h1>Expectation Failed</h1>
> <p>The expectation given in the Expect request-header
> field could not be met by this server.
> The client sent<pre>
>     Expect: 201-created
> </pre>
> </p><p>Only the 100-continue expectation is supported.</p>
> <hr>
> <address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at
> cougar01.scl.lab.tlv.redhat.com Port 80</address>
> </body></html>
Comment 27 Michael Pasternak 2012-08-19 09:24:40 UTC 
> 
> > 2. can you add entire xml request you used in Comment 18 (inc. headers)?
> 
> No, only the body. the expect header I added in the needed box in Poster
> plugin.

obviously you did something wrong with your plugin, there is a problem, but 
i couldn't reproduce 'WS 500 error' you have mentioned.
Comment 28 Rami Vaknin 2012-08-19 10:03:30 UTC 
(In reply to comment #27)
> > 
> > > 2. can you add entire xml request you used in Comment 18 (inc. headers)?
> > 
> > No, only the body. the expect header I added in the needed box in Poster
> > plugin.
> 
> obviously you did something wrong with your plugin, there is a problem, but 
> i couldn't reproduce 'WS 500 error' you have mentioned.

Interesting.

How do you explain the fact that the script add ~30 storage domains successfully and fails just after that? the failure point is different in every running cycle while the script runs in loop and does not change parameters except for different lun guid and lun name.
Comment 29 Michael Pasternak 2012-08-19 11:10:26 UTC 
(In reply to comment #28)
> (In reply to comment #27)
> > > 
> > > > 2. can you add entire xml request you used in Comment 18 (inc. headers)?
> > > 
> > > No, only the body. the expect header I added in the needed box in Poster
> > > plugin.
> > 
> > obviously you did something wrong with your plugin, there is a problem, but 
> > i couldn't reproduce 'WS 500 error' you have mentioned.
> 
> Interesting.
> 
> How do you explain the fact that the script add ~30 storage domains
> successfully and fails just after that? the failure point is different in
> every running cycle while the script runs in loop and does not change
> parameters except for different lun guid and lun name.

Rami, note: i'm talking about facing 'WS 500 error' when you add /expect/
header in your REST plugin.
Comment 30 Michael Pasternak 2012-08-19 13:09:01 UTC 
ok, i fixed that, the issue is that clients set the Expect header and only send the request headers before a PUT/POST of data. This allows the server to respond with errors/redirects/security violations prior to the client sending the request body, but apparently the the clients does not wait until it gets a response and just pushes out the body of the request, which results in the 417 error, to remove the Expect header from the request do:

1. at httpd.conf add 

<IfModule mod_headers.c>
 RequestHeader unset Expect early
</IfModule>

2. service httpd restart

- fixed on cougar01.scl.lab.tlv.redhat.com, so now you can continue testing
SD attachment in 'block' mode, using [expect='201-created'] in SDK.

3. IMPORTANT: this is has to be configured during engine installation
*********************************************************************
Comment 31 Michael Pasternak 2012-08-19 13:35:20 UTC 
integration BZ based on Comment 30 is:
https://bugzilla.redhat.com/show_bug.cgi?id=849442
Comment 32 Rami Vaknin 2012-08-19 20:27:56 UTC 
(In reply to comment #30)
> ok, i fixed that, the issue is that clients set the Expect header and only
> send the request headers before a PUT/POST of data. This allows the server
> to respond with errors/redirects/security violations prior to the client
> sending the request body, but apparently the the clients does not wait until
> it gets a response and just pushes out the body of the request, which
> results in the 417 error, to remove the Expect header from the request do:
> 
> 1. at httpd.conf add 
> 
> <IfModule mod_headers.c>
>  RequestHeader unset Expect early
> </IfModule>
> 
> 2. service httpd restart
> 
> - fixed on cougar01.scl.lab.tlv.redhat.com, so now you can continue testing
> SD attachment in 'block' mode, using [expect='201-created'] in SDK.
> 
> 3. IMPORTANT: this is has to be configured during engine installation
> *********************************************************************

The same happens on the same env with your fixed configuration during storage attachment:

send: 'POST /api/datacenters/238d2039-eeed-4725-a0a5-5c64f7c14d41/storagedomains HTTP/1.1\r\nHost: cougar01.scl.lab.tlv.redhat.com\r\nAccept-Encoding: identity\r\nContent-Length: 1449\r\ncookie: JSESSIONID=Emqg3sHQn+XWHIL8dKiDPE4P\r\nPrefer: persistent-auth\r\nContent-type: application/xml\r\nAuthorization: Basic YWRtaW5AaW50ZXJuYWw6MTIzNDU2\r\n\r\n'
send: '<storage_domain href="/api/storagedomains/c728f303-7e56-4588-a75e-eedf12d32ad0" id="c728f303-7e56-4588-a75e-eedf12d32ad0">\n    <name>36006016012823000ec1d44cbdae6e111</name>\n    <link href="/api/storagedomains/c728f303-7e56-4588-a75e-eedf12d32ad0/permissions" rel="permissions"/>\n    <type>data</type>\n    <status>\n        <state>unattached</state>\n    </status>\n    <master>false</master>\n    <storage>\n        <type>iscsi</type>\n        <volume_group id="5pWee0-yH04-Hfeo-nN4e-FTCI-lijH-m7iUab">\n            <logical_unit id="36006016012823000ec1d44cbdae6e111">\n                <address>10.35.160.107</address>\n                <port>3260</port>\n                <target>iqn.1992-04.com.emc:cx.ckm00121000438.b7</target>\n                <serial>SDGC_VRAID_CKM00121000438</serial>\n                <vendor_id>DGC</vendor_id>\n                <product_id>VRAID</product_id>\n                <lun_mapping>46</lun_mapping>\n                <portal>10.35.160.107:3260,4</portal>\n                <size>322122547200</size>\n                <paths>0</paths>\n                <volume_group_id>5pWee0-yH04-Hfeo-nN4e-FTCI-lijH-m7iUab</volume_group_id>\n                <storage_domain_id>c728f303-7e56-4588-a75e-eedf12d32ad0</storage_domain_id>\n            </logical_unit>\n        </volume_group>\n    </storage>\n    <available>316753838080</available>\n    <used>4294967296</used>\n    <committed>0</committed>\n    <storage_format>v3</storage_format>\n</storage_domain>\n'
reply: 'HTTP/1.1 500 Internal Server Error\r\n'
header: Date: Sun, 19 Aug 2012 22:15:39 GMT
header: Content-Length: 655
header: Connection: close
header: Content-Type: text/html; charset=iso-8859-1
Failed to attach Storage Domain '36006016012823000ec1d44cbdae6e111' to Data Center 'iscsi_dc', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 155, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1107, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/errors.py", line 98, in __init__
    f_detail = params.parseString(res)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 19383, in parseString
    doc = parsexml_(StringIO(inString))
  File "/usr/lib/python2.6/site-packages/ovirtsdk/xml/params.py", line 66, in parsexml_
    doc = etree_.parse(*args, **kwargs)
  File "lxml.etree.pyx", line 2692, in lxml.etree.parse (src/lxml/lxml.etree.c:49594)
  File "parser.pxi", line 1517, in lxml.etree._parseDocument (src/lxml/lxml.etree.c:71540)
  File "parser.pxi", line 1545, in lxml.etree._parseMemoryDocument (src/lxml/lxml.etree.c:71812)
  File "parser.pxi", line 1424, in lxml.etree._parseDoc (src/lxml/lxml.etree.c:70673)
  File "parser.pxi", line 938, in lxml.etree._BaseParser._parseDoc (src/lxml/lxml.etree.c:67442)
  File "parser.pxi", line 539, in lxml.etree._ParserContext._handleParseResultDoc (src/lxml/lxml.etree.c:63824)
  File "parser.pxi", line 625, in lxml.etree._handleParseResult (src/lxml/lxml.etree.c:64745)
  File "parser.pxi", line 565, in lxml.etree._raiseParseError (src/lxml/lxml.etree.c:64088)
XMLSyntaxError: Space required after the Public Identifier, line 1, column 47
Comment 33 Rami Vaknin 2012-08-19 20:31:05 UTC 
Note that the last failed attachment (in comment 32's reply) happend in the 14th storage domain attachment.
Comment 34 Rami Vaknin 2012-08-19 20:36:42 UTC 
One more thing that I've noticed - the failed operations (which get the 500 error) pass successfully in practice - it means for instance that the storage domain attachment that throws the sdk exception - eventually pass successfully in practice (the host becomes attached after ~1 minute), same happens for the storage domain creation failure.
Comment 35 Rami Vaknin 2012-08-19 21:09:46 UTC 
Please note that I get the exception for VMs addition too, here it happend it the 7th vm addition (I ran it without debug and from a different client that does not have your env fix):

Creating VM 'rhel6_7'...  VM 'rhel6_7' creation failed, reason: Space required after the Public Identifier, line 1, column 47
Comment 36 Michael Pasternak 2012-08-20 07:14:19 UTC 
> 
> The same happens on the same env with your fixed configuration during
> storage attachment:
> 
> send: 'POST
> /api/datacenters/238d2039-eeed-4725-a0a5-5c64f7c14d41/storagedomains

it's not the same, as it happens during attachment of SD and not CREATE,
(so it no longer /Expect header issue you faced before), new version of sdk, that capable to handle any type of server error 3.1.0.6 will be available tomorrow.
Comment 37 Michael Pasternak 2012-08-20 07:23:57 UTC 
(In reply to comment #34)
> One more thing that I've noticed - the failed operations (which get the 500
> error) pass successfully in practice - it means for instance that the
> storage domain attachment that throws the sdk exception - eventually pass
> successfully in practice (the host becomes attached after ~1 minute), same
> happens for the storage domain creation failure.

this is not correct and not good way to check/compare, as this server failure 
happens during specific timing/load which you cannot reproduce manually doing 
single operation afterwards,

also cause you mentioned that you face same problem during vms creation,
make me think that BE running in to low resources issue,

wait for sdk 3.1.0.6 to see the exact error returned by the server
Comment 38 Rami Vaknin 2012-08-31 14:58:17 UTC 
Reproduced using rhevm-sdk-3.1.0.7-1.el6ev.noarch on rhevm-3.1.0-14.el6ev.noarch (SI16).

I ran my script on 50 storage domains, it started to fail in the 31th storage domain and this error returned for all the last 20 storage domains attachment.

Note that I use the expect header and your httpd.conf workaround.

Creating Storage Domain '3600601601282300058d0cd325ff3e111'..  Storage Domain '3600601601282300058d0cd325ff3e111' created successfully
Attaching Storage Domain '3600601601282300058d0cd325ff3e111' to Data Center 'dc'..  Failed to attach Storage Domain '3600601601282300058d0cd325ff3e111' to Data Center 'dc', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1106, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 500
reason: Internal Server Error
detail: 
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>500 Internal Server Error</title>
</head><body>
<h1>Internal Server Error</h1>
<p>The server encountered an internal error or
misconfiguration and was unable to complete
your request.</p>
<p>Please contact the server administrator,
 root@localhost and inform them of the time the error occurred,
and anything you might have done that may have
caused the error.</p>
<p>More information about this error may be available
in the server error log.</p>
<hr>
<address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at cougar02.scl.lab.tlv.redhat.com Port 443</address>
</body></html>
Comment 39 Rami Vaknin 2012-08-31 15:06:16 UTC 
Created attachment 608533 [details]
engine.log
Comment 40 Michael Pasternak 2012-09-04 13:08:08 UTC 
[Sun Sep 02 14:25:53 2012] [error] (111)Connection refused: proxy: AJP: attempt to connect to 127.0.0.1:8009 (localhost) failed
[Sun Sep 02 14:25:53 2012] [error] ap_proxy_connect_backend disabling worker for (localhost)
[Sun Sep 02 14:25:53 2012] [error] proxy: AJP: failed to make connection to backend: localhost
[Sun Sep 02 15:02:40 2012] [error] ajp_read_header: ajp_ilink_receive failed
[Sun Sep 02 15:02:40 2012] [error] (70007)The timeout specified has expired: proxy: dialog to [::1]:8009 (localhost) failed
[Sun Sep 02 20:16:03 2012] [error] ajp_read_header: ajp_ilink_receive failed
[Sun Sep 02 20:16:03 2012] [error] (70007)The timeout specified has expired: proxy: dialog to [::1]:8009 (localhost) failed
[Sun Sep 02 20:23:30 2012] [error] ajp_read_header: ajp_ilink_receive failed

ok, i believe this is the same issue as in #818084, #853045,
this is BE issue (BE runs out of resources on heavy loaded env.)
Comment 42 Juan Hernández 2012-09-11 10:23:07 UTC 
Trying to reproduce this in my environment I didn't found any leak of threads or connections in the in the backend. I think that the reason for the timeout is not an overloaded backend, but simply an expired timeout in mod_proxy. The default is that Apache waits up to 60 seconds for network responses, including responses from the application server. The operations on storage domains take an amount of time that is very close to this timeout. Some examples from my environment (after attaching 24 storage domains in a row):

24: 1IET_00010019
create: 0:00:23.589888
attach: 0:00:40.433970
activate: 0:00:40.433970

25: 1IET_0001001a
create: 0:00:37.670729
attach: 0:00:38.070014
activate: 0:00:38.070014

26: 1IET_0001001b
create: 0:00:39.049241
attach: 0:01:08.289056
activate: 0:01:08.289056

As you can see storage domain number 26 takes more than one minute to attach and activate. In this situation Apache will just cancel the operation because it doesn't receive any response from the application server.

This timeout can be controlled globally with the Timeout directive or it can be controlled in the AJP proxy configuration like this (in /etc/httpd/conf.d/ovirt-engine.conf):

ProxyPass / ajp://localhost:8702/ retry=5 timeout=300

I think this is what we should do. I am repeating the test with the change in the configuration and with 100 storage domains. If it works correctly I will submit a patch to perform this change in the configuration.

Rami, can you apply this change and repeat the test in your environment?
Comment 43 Juan Hernández 2012-09-11 17:03:31 UTC 
Increasing the timeout to 300 seconds allows the creation of the 100 storage domains, at least in my environment, which is not specially fast.

The suggested change is available here:

http://gerrit.ovirt.org/7933
Comment 44 Rami Vaknin 2012-09-11 22:25:35 UTC 
Still happens with the change, but this time my test is a bit different since storage domains addition is extreamly slow in my env, I'm not sure what's the reason yet but there are few differences from my last test:

* Much much more loaded env - 224 hosts, 200 vms, hundreds of storage domains
* Different storage server (XtremIO instead of VNX due to VNX upgrade)
* Different patched vdsm version
* The 500 error was given during the 15th storage domains attachment, the activation succeded so the attachment passed successfully (note my comment #34)

I believe that the first reason makes the difference (while assuming that the bug analysis and fix are correct) so timeout of 300 could still be low.

I'll test this fix again on env which is identical to the original one in the next builds.

Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
Creating Storage Domain '3514f0c5695800463'..  Storage Domain '3514f0c5695800463' created successfully
Attaching Storage Domain '3514f0c5695800463' to Data Center 'dc_fsimonce'..  Failed to attach Storage Domain '3514f0c5695800463' to Data Center 'dc_fsimonce', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1106, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 500
reason: Internal Server Error
detail: 
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
<html><head>
<title>500 Internal Server Error</title>
</head><body>
<h1>Internal Server Error</h1>
<p>The server encountered an internal error or
misconfiguration and was unable to complete
your request.</p>
<p>Please contact the server administrator,
 root@localhost and inform them of the time the error occurred,
and anything you might have done that may have
caused the error.</p>
<p>More information about this error may be available
in the server error log.</p>
<hr>
<address>Apache/2.2.17 (Red Hat Enterprise Web Server) Server at cougar01.scl.lab.tlv.redhat.com Port 443</address>
</body></html>


Activating Storage Domain '3514f0c5695800463'..  Storage Domain '3514f0c5695800463' activated successfully
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
Creating Storage Domain '3514f0c5695800480'..  Storage Domain '3514f0c5695800480' created successfully
Attaching Storage Domain '3514f0c5695800480' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800480' attached to Data Center 'dc_fsimonce' successfully
Activating Storage Domain '3514f0c5695800480'..  Storage Domain '3514f0c5695800480' activated successfully
Comment 45 Juan Hernández 2012-09-12 08:04:00 UTC 
It would be great if you can measure the times that it takes to create/attach/activate the storage domains in your environment. Set the timeout to a very high value (1 hour, for example) then run the test and get those measurements, then we can take the values and decide which is a reasonable timeout.
Comment 46 Rami Vaknin 2012-09-12 09:55:02 UTC 
Results of successful storage domain:

1347449987.98
Creating Storage Domain '3514f0c56958004c0'..  Storage Domain '3514f0c56958004c0' created successfully
1347450051.61
Attaching Storage Domain '3514f0c56958004c0' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004c0' attached to Data Center 'dc_fsimonce' successfully
1347450237.67
Activating Storage Domain '3514f0c56958004c0'..  Storage Domain '3514f0c56958004c0' activated successfully
1347450537.77


Create: 63.63 seconds
Attach: 186.06 seconds
Activate: 300.10 seconds
Comment 47 Rami Vaknin 2012-09-13 04:25:45 UTC 
I ran the test again on ~50 storage domains while the timeout 3600, the longest operation took 428.39 seconds (see list at the end of the below output).
In addition, there were no 500 error page anymore!!!

Connecting to engine core...  [OK]
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347454831.73
*** Operation took: 0.0 seconds
Creating Storage Domain '3514f0c5695800466'..  Failed to create Storage Domain '3514f0c5695800466', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 139, in create
    self.getSdkProxy().storagedomains.add( self.getSdParams(), expect='201-created' )
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 3829, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot add Storage. The Storage Domain name is already in use.

1347454844.1
*** Operation took: 12.3699998856 seconds
Attaching Storage Domain '3514f0c5695800466' to Data Center 'dc_fsimonce'..  Failed to attach Storage Domain '3514f0c5695800466' to Data Center 'dc_fsimonce', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1106, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot attach Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347454848.26
*** Operation took: 4.16000008583 seconds
Activating Storage Domain '3514f0c5695800466'..  Failed to activate Storage Domain '3514f0c5695800466', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 168, in activate
    self.getSdkProxy().datacenters.get(self.getDatacenter()).storagedomains.get(self.getName()).activate()
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1062, in activate
    headers={"Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot activate Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347454855.28
*** Operation took: 7.01999998093 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347454925.92
*** Operation took: 70.6400001049 seconds
Creating Storage Domain '3514f0c5695800467'..  Failed to create Storage Domain '3514f0c5695800467', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 139, in create
    self.getSdkProxy().storagedomains.add( self.getSdParams(), expect='201-created' )
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 3829, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot add Storage. The Storage Domain name is already in use.

1347454935.48
*** Operation took: 9.55999994278 seconds
Attaching Storage Domain '3514f0c5695800467' to Data Center 'dc_fsimonce'..  Failed to attach Storage Domain '3514f0c5695800467' to Data Center 'dc_fsimonce', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1106, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot attach Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347454938.68
*** Operation took: 3.20000004768 seconds
Activating Storage Domain '3514f0c5695800467'..  Failed to activate Storage Domain '3514f0c5695800467', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 168, in activate
    self.getSdkProxy().datacenters.get(self.getDatacenter()).storagedomains.get(self.getName()).activate()
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1062, in activate
    headers={"Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot activate Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347454950.21
*** Operation took: 11.5299999714 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347455022.63
*** Operation took: 72.4200000763 seconds
Creating Storage Domain '3514f0c5695800468'..  Failed to create Storage Domain '3514f0c5695800468', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 139, in create
    self.getSdkProxy().storagedomains.add( self.getSdParams(), expect='201-created' )
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 3829, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot add Storage. The Storage Domain name is already in use.

1347455039.37
*** Operation took: 16.7399997711 seconds
Attaching Storage Domain '3514f0c5695800468' to Data Center 'dc_fsimonce'..  Failed to attach Storage Domain '3514f0c5695800468' to Data Center 'dc_fsimonce', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1106, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot attach Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347455041.18
*** Operation took: 1.8100001812 seconds
Activating Storage Domain '3514f0c5695800468'..  Failed to activate Storage Domain '3514f0c5695800468', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 168, in activate
    self.getSdkProxy().datacenters.get(self.getDatacenter()).storagedomains.get(self.getName()).activate()
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1062, in activate
    headers={"Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot activate Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347455049.64
*** Operation took: 8.46000003815 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347455115.35
*** Operation took: 65.7099997997 seconds
Creating Storage Domain '3514f0c5695800469'..  Failed to create Storage Domain '3514f0c5695800469', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 139, in create
    self.getSdkProxy().storagedomains.add( self.getSdParams(), expect='201-created' )
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 3829, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot add Storage. The Storage Domain name is already in use.

1347455127.35
*** Operation took: 12.0 seconds
Attaching Storage Domain '3514f0c5695800469' to Data Center 'dc_fsimonce'..  Failed to attach Storage Domain '3514f0c5695800469' to Data Center 'dc_fsimonce', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 156, in attachToDc
    self.getSdkProxy().datacenters.get(datacenter).storagedomains.add(sd)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1106, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot attach Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347455129.23
*** Operation took: 1.88000011444 seconds
Activating Storage Domain '3514f0c5695800469'..  Failed to activate Storage Domain '3514f0c5695800469', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 168, in activate
    self.getSdkProxy().datacenters.get(self.getDatacenter()).storagedomains.get(self.getName()).activate()
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1062, in activate
    headers={"Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot activate Storage. The relevant Storage Domain is inaccessible.
-Please handle Storage Domain issues and retry the operation.

1347455142.85
*** Operation took: 13.6199998856 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347455207.9
*** Operation took: 65.0500001907 seconds
Creating Storage Domain '3514f0c5695800470'..  Failed to create Storage Domain '3514f0c5695800470', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 139, in create
    self.getSdkProxy().storagedomains.add( self.getSdParams(), expect='201-created' )
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 3829, in add
    headers={"Expect":expect, "Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 117, in add
    return self.request('POST', url, body, headers)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Cannot add Storage. The Storage Domain name is already in use.

1347455218.03
*** Operation took: 10.129999876 seconds
Attaching Storage Domain '3514f0c5695800470' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800470' attached to Data Center 'dc_fsimonce' successfully
1347455395.18
*** Operation took: 177.150000095 seconds
Activating Storage Domain '3514f0c5695800470'..  Storage Domain '3514f0c5695800470' activated successfully
1347455544.03
*** Operation took: 148.849999905 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347455622.36
*** Operation took: 78.3299999237 seconds
Creating Storage Domain '3514f0c5695800471'..  Storage Domain '3514f0c5695800471' created successfully
1347455666.8
*** Operation took: 44.4400000572 seconds
Attaching Storage Domain '3514f0c5695800471' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800471' attached to Data Center 'dc_fsimonce' successfully
1347455858.49
*** Operation took: 191.690000057 seconds
Activating Storage Domain '3514f0c5695800471'..  Storage Domain '3514f0c5695800471' activated successfully
1347456015.08
*** Operation took: 156.589999914 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347456110.55
*** Operation took: 95.4700000286 seconds
Creating Storage Domain '3514f0c5695800472'..  Storage Domain '3514f0c5695800472' created successfully
1347456166.5
*** Operation took: 55.9500000477 seconds
Attaching Storage Domain '3514f0c5695800472' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800472' attached to Data Center 'dc_fsimonce' successfully
1347456364.75
*** Operation took: 198.25 seconds
Activating Storage Domain '3514f0c5695800472'..  Storage Domain '3514f0c5695800472' activated successfully
1347456577.55
*** Operation took: 212.799999952 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347456673.38
*** Operation took: 95.8300001621 seconds
Creating Storage Domain '3514f0c569580047a'..  Storage Domain '3514f0c569580047a' created successfully
1347456712.02
*** Operation took: 38.6399998665 seconds
Attaching Storage Domain '3514f0c569580047a' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580047a' attached to Data Center 'dc_fsimonce' successfully
1347456924.98
*** Operation took: 212.960000038 seconds
Activating Storage Domain '3514f0c569580047a'..  Storage Domain '3514f0c569580047a' activated successfully
1347457131.06
*** Operation took: 206.079999924 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347457224.75
*** Operation took: 93.6900000572 seconds
Creating Storage Domain '3514f0c569580047b'..  Storage Domain '3514f0c569580047b' created successfully
1347457283.39
*** Operation took: 58.6400001049 seconds
Attaching Storage Domain '3514f0c569580047b' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580047b' attached to Data Center 'dc_fsimonce' successfully
1347457470.77
*** Operation took: 187.379999876 seconds
Activating Storage Domain '3514f0c569580047b'..  Storage Domain '3514f0c569580047b' activated successfully
1347457724.8
*** Operation took: 254.029999971 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347457812.4
*** Operation took: 87.6000001431 seconds
Creating Storage Domain '3514f0c569580047c'..  Storage Domain '3514f0c569580047c' created successfully
1347457873.31
*** Operation took: 60.9099998474 seconds
Attaching Storage Domain '3514f0c569580047c' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580047c' attached to Data Center 'dc_fsimonce' successfully
1347458059.12
*** Operation took: 185.809999943 seconds
Activating Storage Domain '3514f0c569580047c'..  Storage Domain '3514f0c569580047c' activated successfully
1347458237.11
*** Operation took: 177.99000001 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347458340.54
*** Operation took: 103.430000067 seconds
Creating Storage Domain '3514f0c569580047d'..  Storage Domain '3514f0c569580047d' created successfully
1347458389.46
*** Operation took: 48.9200000763 seconds
Attaching Storage Domain '3514f0c569580047d' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580047d' attached to Data Center 'dc_fsimonce' successfully
1347458629.93
*** Operation took: 240.470000029 seconds
Activating Storage Domain '3514f0c569580047d'..  Storage Domain '3514f0c569580047d' activated successfully
1347458808.46
*** Operation took: 178.529999971 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347458925.04
*** Operation took: 116.579999924 seconds
Creating Storage Domain '3514f0c569580047e'..  Storage Domain '3514f0c569580047e' created successfully
1347458973.37
*** Operation took: 48.3299999237 seconds
Attaching Storage Domain '3514f0c569580047e' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580047e' attached to Data Center 'dc_fsimonce' successfully
1347459204.84
*** Operation took: 231.470000029 seconds
Activating Storage Domain '3514f0c569580047e'..  Storage Domain '3514f0c569580047e' activated successfully
1347459427.93
*** Operation took: 223.090000153 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347459520.26
*** Operation took: 92.3299999237 seconds
Creating Storage Domain '3514f0c5695800483'..  Storage Domain '3514f0c5695800483' created successfully
1347459603.51
*** Operation took: 83.25 seconds
Attaching Storage Domain '3514f0c5695800483' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800483' attached to Data Center 'dc_fsimonce' successfully
1347459826.86
*** Operation took: 223.349999905 seconds
Activating Storage Domain '3514f0c5695800483'..  Storage Domain '3514f0c5695800483' activated successfully
1347460036.35
*** Operation took: 209.49000001 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347460160.53
*** Operation took: 124.180000067 seconds
Creating Storage Domain '3514f0c5695800484'..  Storage Domain '3514f0c5695800484' created successfully
1347460209.3
*** Operation took: 48.7699999809 seconds
Attaching Storage Domain '3514f0c5695800484' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800484' attached to Data Center 'dc_fsimonce' successfully
1347460453.29
*** Operation took: 243.99000001 seconds
Activating Storage Domain '3514f0c5695800484'..  Storage Domain '3514f0c5695800484' activated successfully
1347460705.71
*** Operation took: 252.420000076 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347460822.81
*** Operation took: 117.099999905 seconds
Creating Storage Domain '3514f0c5695800485'..  Storage Domain '3514f0c5695800485' created successfully
1347460874.99
*** Operation took: 52.1800000668 seconds
Attaching Storage Domain '3514f0c5695800485' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800485' attached to Data Center 'dc_fsimonce' successfully
1347461128.64
*** Operation took: 253.650000095 seconds
Activating Storage Domain '3514f0c5695800485'..  Storage Domain '3514f0c5695800485' activated successfully
1347461406.97
*** Operation took: 278.329999924 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347461531.94
*** Operation took: 124.970000029 seconds
Creating Storage Domain '3514f0c5695800486'..  Storage Domain '3514f0c5695800486' created successfully
1347461592.34
*** Operation took: 60.3999998569 seconds
Attaching Storage Domain '3514f0c5695800486' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800486' attached to Data Center 'dc_fsimonce' successfully
1347461889.2
*** Operation took: 296.860000134 seconds
Activating Storage Domain '3514f0c5695800486'..  Storage Domain '3514f0c5695800486' activated successfully
1347462196.22
*** Operation took: 307.019999981 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347462309.77
*** Operation took: 113.549999952 seconds
Creating Storage Domain '3514f0c5695800487'..  Storage Domain '3514f0c5695800487' created successfully
1347462369.72
*** Operation took: 59.9500000477 seconds
Attaching Storage Domain '3514f0c5695800487' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800487' attached to Data Center 'dc_fsimonce' successfully
1347462587.03
*** Operation took: 217.309999943 seconds
Activating Storage Domain '3514f0c5695800487'..  Storage Domain '3514f0c5695800487' activated successfully
1347462816.58
*** Operation took: 229.549999952 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347462930.73
*** Operation took: 114.150000095 seconds
Creating Storage Domain '3514f0c569580048f'..  Storage Domain '3514f0c569580048f' created successfully
1347462991.99
*** Operation took: 61.2599999905 seconds
Attaching Storage Domain '3514f0c569580048f' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580048f' attached to Data Center 'dc_fsimonce' successfully
1347463242.55
*** Operation took: 250.559999943 seconds
Activating Storage Domain '3514f0c569580048f'..  Storage Domain '3514f0c569580048f' activated successfully
1347463516.15
*** Operation took: 273.600000143 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347463640.59
*** Operation took: 124.439999819 seconds
Creating Storage Domain '3514f0c5695800498'..  Storage Domain '3514f0c5695800498' created successfully
1347463692.3
*** Operation took: 51.7100000381 seconds
Attaching Storage Domain '3514f0c5695800498' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800498' attached to Data Center 'dc_fsimonce' successfully
1347463994.29
*** Operation took: 301.99000001 seconds
Activating Storage Domain '3514f0c5695800498'..  Storage Domain '3514f0c5695800498' activated successfully
1347464330.6
*** Operation took: 336.309999943 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347464440.93
*** Operation took: 110.330000162 seconds
Creating Storage Domain '3514f0c5695800499'..  Storage Domain '3514f0c5695800499' created successfully
1347464515.69
*** Operation took: 74.7599999905 seconds
Attaching Storage Domain '3514f0c5695800499' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c5695800499' attached to Data Center 'dc_fsimonce' successfully
1347464817.72
*** Operation took: 302.029999971 seconds
Activating Storage Domain '3514f0c5695800499'..  Storage Domain '3514f0c5695800499' activated successfully
1347465047.52
*** Operation took: 229.799999952 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347465146.89
*** Operation took: 99.370000124 seconds
Creating Storage Domain '3514f0c569580049a'..  Storage Domain '3514f0c569580049a' created successfully
1347465240.23
*** Operation took: 93.3399999142 seconds
Attaching Storage Domain '3514f0c569580049a' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580049a' attached to Data Center 'dc_fsimonce' successfully
1347465550.01
*** Operation took: 309.779999971 seconds
Activating Storage Domain '3514f0c569580049a'..  Storage Domain '3514f0c569580049a' activated successfully
1347465891.92
*** Operation took: 341.910000086 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347466018.19
*** Operation took: 126.269999981 seconds
Creating Storage Domain '3514f0c569580049b'..  Storage Domain '3514f0c569580049b' created successfully
1347466075.7
*** Operation took: 57.5099999905 seconds
Attaching Storage Domain '3514f0c569580049b' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580049b' attached to Data Center 'dc_fsimonce' successfully
1347466396.91
*** Operation took: 321.210000038 seconds
Activating Storage Domain '3514f0c569580049b'..  Storage Domain '3514f0c569580049b' activated successfully
1347466722.75
*** Operation took: 325.839999914 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347466852.0
*** Operation took: 129.25 seconds
Creating Storage Domain '3514f0c569580049c'..  Storage Domain '3514f0c569580049c' created successfully
1347466923.74
*** Operation took: 71.7400000095 seconds
Attaching Storage Domain '3514f0c569580049c' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c569580049c' attached to Data Center 'dc_fsimonce' successfully
1347467273.59
*** Operation took: 349.849999905 seconds
Activating Storage Domain '3514f0c569580049c'..  Storage Domain '3514f0c569580049c' activated successfully
1347467570.83
*** Operation took: 297.24000001 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347467705.13
*** Operation took: 134.300000191 seconds
Creating Storage Domain '3514f0c56958004a3'..  Storage Domain '3514f0c56958004a3' created successfully
1347467778.54
*** Operation took: 73.4099998474 seconds
Attaching Storage Domain '3514f0c56958004a3' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004a3' attached to Data Center 'dc_fsimonce' successfully
1347468126.44
*** Operation took: 347.900000095 seconds
Activating Storage Domain '3514f0c56958004a3'..  Storage Domain '3514f0c56958004a3' activated successfully
1347468499.13
*** Operation took: 372.690000057 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347468646.58
*** Operation took: 147.449999809 seconds
Creating Storage Domain '3514f0c56958004a4'..  Storage Domain '3514f0c56958004a4' created successfully
1347468752.45
*** Operation took: 105.870000124 seconds
Attaching Storage Domain '3514f0c56958004a4' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004a4' attached to Data Center 'dc_fsimonce' successfully
1347469142.81
*** Operation took: 390.359999895 seconds
Activating Storage Domain '3514f0c56958004a4'..  Storage Domain '3514f0c56958004a4' activated successfully
1347469542.96
*** Operation took: 400.150000095 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347469686.39
*** Operation took: 143.430000067 seconds
Creating Storage Domain '3514f0c56958004a5'..  Storage Domain '3514f0c56958004a5' created successfully
1347469758.43
*** Operation took: 72.0399999619 seconds
Attaching Storage Domain '3514f0c56958004a5' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004a5' attached to Data Center 'dc_fsimonce' successfully
1347470171.78
*** Operation took: 413.349999905 seconds
Activating Storage Domain '3514f0c56958004a5'..  Storage Domain '3514f0c56958004a5' activated successfully
1347470499.28
*** Operation took: 327.5 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347470634.32
*** Operation took: 135.039999962 seconds
Creating Storage Domain '3514f0c56958004a6'..  Storage Domain '3514f0c56958004a6' created successfully
1347470705.84
*** Operation took: 71.5199999809 seconds
Attaching Storage Domain '3514f0c56958004a6' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004a6' attached to Data Center 'dc_fsimonce' successfully
1347471106.35
*** Operation took: 400.50999999 seconds
Activating Storage Domain '3514f0c56958004a6'..  Storage Domain '3514f0c56958004a6' activated successfully
1347471452.88
*** Operation took: 346.53000021 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347471603.68
*** Operation took: 150.799999952 seconds
Creating Storage Domain '3514f0c56958004a7'..  Storage Domain '3514f0c56958004a7' created successfully
1347471726.55
*** Operation took: 122.869999886 seconds
Attaching Storage Domain '3514f0c56958004a7' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004a7' attached to Data Center 'dc_fsimonce' successfully
1347472058.46
*** Operation took: 331.910000086 seconds
Activating Storage Domain '3514f0c56958004a7'..  Storage Domain '3514f0c56958004a7' activated successfully
1347472368.86
*** Operation took: 310.399999857 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma01' in Data Center 'dc_fsimonce'
1347472488.08
*** Operation took: 119.220000029 seconds
Creating Storage Domain '3514f0c56958004af'..  Storage Domain '3514f0c56958004af' created successfully
1347472577.54
*** Operation took: 89.4600000381 seconds
Attaching Storage Domain '3514f0c56958004af' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004af' attached to Data Center 'dc_fsimonce' successfully
1347472944.65
*** Operation took: 367.110000134 seconds
Activating Storage Domain '3514f0c56958004af'..  Storage Domain '3514f0c56958004af' activated successfully
1347473237.6
*** Operation took: 292.949999809 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347473365.06
*** Operation took: 127.460000038 seconds
Creating Storage Domain '3514f0c56958004b0'..  Storage Domain '3514f0c56958004b0' created successfully
1347473431.51
*** Operation took: 66.4500000477 seconds
Attaching Storage Domain '3514f0c56958004b0' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004b0' attached to Data Center 'dc_fsimonce' successfully
1347473783.03
*** Operation took: 351.519999981 seconds
Activating Storage Domain '3514f0c56958004b0'..  Storage Domain '3514f0c56958004b0' activated successfully
1347474141.83
*** Operation took: 358.799999952 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347474266.46
*** Operation took: 124.630000114 seconds
Creating Storage Domain '3514f0c56958004b8'..  Storage Domain '3514f0c56958004b8' created successfully
1347474353.07
*** Operation took: 86.6099998951 seconds
Attaching Storage Domain '3514f0c56958004b8' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004b8' attached to Data Center 'dc_fsimonce' successfully
1347474673.96
*** Operation took: 320.890000105 seconds
Activating Storage Domain '3514f0c56958004b8'..  Storage Domain '3514f0c56958004b8' activated successfully
1347475053.06
*** Operation took: 379.099999905 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347475183.04
*** Operation took: 129.980000019 seconds
Creating Storage Domain '3514f0c56958004b9'..  Storage Domain '3514f0c56958004b9' created successfully
1347475272.05
*** Operation took: 89.0099999905 seconds
Attaching Storage Domain '3514f0c56958004b9' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004b9' attached to Data Center 'dc_fsimonce' successfully
1347475627.05
*** Operation took: 355.0 seconds
Activating Storage Domain '3514f0c56958004b9'..  Storage Domain '3514f0c56958004b9' activated successfully
1347475966.62
*** Operation took: 339.569999933 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347476098.76
*** Operation took: 132.140000105 seconds
Creating Storage Domain '3514f0c56958004ba'..  Storage Domain '3514f0c56958004ba' created successfully
1347476190.53
*** Operation took: 91.7699999809 seconds
Attaching Storage Domain '3514f0c56958004ba' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004ba' attached to Data Center 'dc_fsimonce' successfully
1347476547.73
*** Operation took: 357.200000048 seconds
Activating Storage Domain '3514f0c56958004ba'..  Storage Domain '3514f0c56958004ba' activated successfully
1347476886.24
*** Operation took: 338.50999999 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347477008.48
*** Operation took: 122.24000001 seconds
Creating Storage Domain '3514f0c56958004bb'..  Storage Domain '3514f0c56958004bb' created successfully
1347477093.24
*** Operation took: 84.7599999905 seconds
Attaching Storage Domain '3514f0c56958004bb' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004bb' attached to Data Center 'dc_fsimonce' successfully
1347477456.46
*** Operation took: 363.220000029 seconds
Activating Storage Domain '3514f0c56958004bb'..  Storage Domain '3514f0c56958004bb' activated successfully
1347477884.85
*** Operation took: 428.389999866 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347478011.3
*** Operation took: 126.450000048 seconds
Creating Storage Domain '3514f0c56958004bc'..  Storage Domain '3514f0c56958004bc' created successfully
1347478115.05
*** Operation took: 103.75 seconds
Attaching Storage Domain '3514f0c56958004bc' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004bc' attached to Data Center 'dc_fsimonce' successfully
1347478386.39
*** Operation took: 271.340000153 seconds
Activating Storage Domain '3514f0c56958004bc'..  Storage Domain '3514f0c56958004bc' activated successfully
1347478735.72
*** Operation took: 349.329999924 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347478876.27
*** Operation took: 140.549999952 seconds
Creating Storage Domain '3514f0c56958004c1'..  Storage Domain '3514f0c56958004c1' created successfully
1347478947.1
*** Operation took: 70.8299999237 seconds
Attaching Storage Domain '3514f0c56958004c1' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004c1' attached to Data Center 'dc_fsimonce' successfully
1347479218.4
*** Operation took: 271.300000191 seconds
Activating Storage Domain '3514f0c56958004c1'..  Storage Domain '3514f0c56958004c1' activated successfully
1347479527.41
*** Operation took: 309.00999999 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347479652.4
*** Operation took: 124.99000001 seconds
Creating Storage Domain '3514f0c56958004c2'..  Storage Domain '3514f0c56958004c2' created successfully
1347479725.63
*** Operation took: 73.2300000191 seconds
Attaching Storage Domain '3514f0c56958004c2' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004c2' attached to Data Center 'dc_fsimonce' successfully
1347480022.41
*** Operation took: 296.779999971 seconds
Activating Storage Domain '3514f0c56958004c2'..  Storage Domain '3514f0c56958004c2' activated successfully
1347480259.17
*** Operation took: 236.75999999 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347480374.03
*** Operation took: 114.859999895 seconds
Creating Storage Domain '3514f0c56958004c3'..  Storage Domain '3514f0c56958004c3' created successfully
1347480476.84
*** Operation took: 102.809999943 seconds
Attaching Storage Domain '3514f0c56958004c3' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004c3' attached to Data Center 'dc_fsimonce' successfully
1347480795.58
*** Operation took: 318.74000001 seconds
Activating Storage Domain '3514f0c56958004c3'..  Storage Domain '3514f0c56958004c3' activated successfully
1347481064.95
*** Operation took: 269.370000124 seconds
Looking for available Host for Storage Domain Creation in Data Center 'dc_fsimonce'...  Found Host 'puma02' in Data Center 'dc_fsimonce'
1347481189.03
*** Operation took: 124.079999924 seconds
Creating Storage Domain '3514f0c56958004c4'..  Storage Domain '3514f0c56958004c4' created successfully
1347481279.62
*** Operation took: 90.5899999142 seconds
Attaching Storage Domain '3514f0c56958004c4' to Data Center 'dc_fsimonce'..  Storage Domain '3514f0c56958004c4' attached to Data Center 'dc_fsimonce' successfully
1347481523.52
*** Operation took: 243.900000095 seconds
Activating Storage Domain '3514f0c56958004c4'..  Failed to activate Storage Domain '3514f0c56958004c4', reason:

Traceback (most recent call last):
  File "/root/scale_scripts/sdk/storage.py", line 168, in activate
    self.getSdkProxy().datacenters.get(self.getDatacenter()).storagedomains.get(self.getName()).activate()
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/brokers.py", line 1062, in activate
    headers={"Correlation-Id":correlation_id})
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 128, in request
    last=last)
  File "/usr/lib/python2.6/site-packages/ovirtsdk/infrastructure/proxy.py", line 154, in __doRequest
    raise RequestError, response
RequestError: 
status: 400
reason: Bad Request
detail: Failed to activate Storage due to an error on the Data Center master Storage Domain.
-Please activate the master Storage Domain first.

1347481577.69
*** Operation took: 54.1700000763 seconds
[root@cougar02 sdk]# 

Sorted list of durations:
[0.0, 1.8100001811981201, 1.880000114440918, 3.2000000476837158, 4.1600000858306885, 7.0199999809265137, 8.4600000381469727, 9.559999942779541, 10.129999876022339, 11.529999971389771, 12.0, 12.369999885559082, 13.619999885559082, 16.739999771118164, 38.639999866485596, 44.440000057220459, 48.329999923706055, 48.769999980926514, 48.920000076293945, 51.710000038146973, 52.180000066757202, 54.170000076293945, 55.950000047683716, 57.509999990463257, 58.640000104904175, 59.950000047683716, 60.399999856948853, 60.909999847412109, 61.259999990463257, 65.050000190734863, 65.709999799728394, 66.450000047683716, 70.640000104904175, 70.829999923706055, 71.519999980926514, 71.740000009536743, 72.039999961853027, 72.420000076293945, 73.230000019073486, 73.409999847412109, 74.759999990463257, 78.329999923706055, 83.25, 84.759999990463257, 86.609999895095825, 87.600000143051147, 89.009999990463257, 89.460000038146973, 90.589999914169312, 91.769999980926514, 92.329999923706055, 93.339999914169312, 93.690000057220459, 95.470000028610229, 95.830000162124634, 99.370000123977661, 102.80999994277954, 103.4300000667572, 103.75, 105.87000012397766, 110.33000016212463, 113.54999995231628, 114.15000009536743, 114.85999989509583, 116.57999992370605, 117.09999990463257, 119.22000002861023, 122.24000000953674, 122.86999988555908, 124.07999992370605, 124.1800000667572, 124.43999981880188, 124.63000011444092, 124.97000002861023, 124.99000000953674, 126.26999998092651, 126.45000004768372, 127.46000003814697, 129.25, 129.98000001907349, 132.14000010490417, 134.30000019073486, 135.03999996185303, 140.54999995231628, 143.4300000667572, 147.44999980926514, 148.84999990463257, 150.79999995231628, 156.58999991416931, 177.15000009536743, 177.99000000953674, 178.52999997138977, 185.80999994277954, 187.37999987602234, 191.69000005722046, 198.25, 206.07999992370605, 209.49000000953674, 212.79999995231628, 212.96000003814697, 217.30999994277954, 223.09000015258789, 223.34999990463257, 229.54999995231628, 229.79999995231628, 231.47000002861023, 236.75999999046326, 240.47000002861023, 243.90000009536743, 243.99000000953674, 250.55999994277954, 252.42000007629395, 253.65000009536743, 254.02999997138977, 269.37000012397766, 271.30000019073486, 271.34000015258789, 273.60000014305115, 278.32999992370605, 292.94999980926514, 296.77999997138977, 296.8600001335144, 297.24000000953674, 301.99000000953674, 302.02999997138977, 307.01999998092651, 309.00999999046326, 309.77999997138977, 310.39999985694885, 318.74000000953674, 320.89000010490417, 321.21000003814697, 325.83999991416931, 327.5, 331.91000008583069, 336.30999994277954, 338.50999999046326, 339.5699999332428, 341.91000008583069, 346.53000020980835, 347.90000009536743, 349.32999992370605, 349.84999990463257, 351.51999998092651, 355.0, 357.20000004768372, 358.79999995231628, 363.22000002861023, 367.1100001335144, 372.69000005722046, 379.09999990463257, 390.35999989509583, 400.15000009536743, 400.50999999046326, 413.34999990463257, 428.3899998664856]
Comment 48 Juan Hernández 2012-09-13 09:54:33 UTC 
I updated the patch to set the timeout to 10 minutes. This should be enough for this use case.
Comment 49 Juan Hernández 2012-09-19 13:15:56 UTC 
The change to increase the timeout (to 10 minute) has been merged upstream:

http://gerrit.ovirt.org/gitweb?p=ovirt-engine.git;a=commit;h=4ed888feb80910f55c9cf4f5944818ff5e017666
Comment 50 Itamar Heim 2012-09-20 11:06:13 UTC 
downstream patch:
https://gerrit.eng.lab.tlv.redhat.com/#/c/2190/
Comment 56 Rami Vaknin 2012-11-12 13:03:48 UTC 
ATM, I can't verify it on high scale due to:
Bug 875709 - [Scalability] iscsi storage domain creation fails due to timed-out getDeviceList