2018-07-12 16:41:27.268578 | [Zuul] Launched by status-openstack.rtp.openenglab.netapp.com
2018-07-12 16:41:27.268622 | [Zuul] Building remotely on devstack-xenial-eseries-FCP-provider-59-fcp-156580 in workspace /home/jenkins/workspace/cinder-eseries-FCP
2018-07-12 16:41:28.884583 | Detailed logs: http://logs.openstack.netapp.com/logs/59/572759/7/upstream-eseries-check/cinder-eseries-FCP/93e4faf/
2018-07-12 16:41:28.885626 | [Zuul] Task exit code: 0
2018-07-12 16:41:29.631647 | Host & kernel
2018-07-12 16:41:29.631694 | =============
2018-07-12 16:41:29.632120 | Linux devstack-xenial-eseries-fcp-provider-59-fcp-156580 4.4.0-130-generic #156-Ubuntu SMP Thu Jun 14 08:53:28 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
2018-07-12 16:41:29.632164 | Network interface addresses...
2018-07-12 16:41:29.632187 | ==============================
2018-07-12 16:41:29.632914 | 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1
2018-07-12 16:41:29.632964 |     link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
2018-07-12 16:41:29.632987 |     inet 127.0.0.1/8 scope host lo
2018-07-12 16:41:29.633013 |        valid_lft forever preferred_lft forever
2018-07-12 16:41:29.633031 |     inet6 ::1/128 scope host 
2018-07-12 16:41:29.633057 |        valid_lft forever preferred_lft forever
2018-07-12 16:41:29.633106 | 2: ens3: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1400 qdisc pfifo_fast state UP group default qlen 1000
2018-07-12 16:41:29.633136 |     link/ether fa:16:3e:94:a1:6b brd ff:ff:ff:ff:ff:ff
2018-07-12 16:41:29.633180 |     inet 192.168.100.3/24 brd 192.168.100.255 scope global ens3
2018-07-12 16:41:29.633209 |        valid_lft forever preferred_lft forever
2018-07-12 16:41:29.633236 |     inet6 fe80::f816:3eff:fe94:a16b/64 scope link 
2018-07-12 16:41:29.633261 |        valid_lft forever preferred_lft forever
2018-07-12 16:41:29.633278 | Network routing tables...
2018-07-12 16:41:29.633295 | =========================
2018-07-12 16:41:29.633529 | default via 192.168.100.1 dev ens3 
2018-07-12 16:41:29.633575 | 192.168.100.0/24 dev ens3  proto kernel  scope link  src 192.168.100.3 
2018-07-12 16:41:29.634246 | fe80::/64 dev ens3  proto kernel  metric 256  mtu 1400 pref medium
2018-07-12 16:41:29.634274 | Network neighbors...
2018-07-12 16:41:29.634291 | ====================
2018-07-12 16:41:29.635023 | 192.168.100.1 dev ens3 lladdr fa:16:3e:a4:9f:75 DELAY
2018-07-12 16:41:29.635052 | Route to Git mirror...
2018-07-12 16:41:29.635069 | ======================
2018-07-12 16:41:29.659988 | connect: Network is unreachable
2018-07-12 16:41:29.660102 | /tmp/02-a3a894bf8e3f45e580ff15428efc7b5e.sh: 24: /tmp/02-a3a894bf8e3f45e580ff15428efc7b5e.sh: traceroute: not found
2018-07-12 16:41:29.660205 | [Zuul] Task exit code: 0
2018-07-12 16:41:30.301512 | + sudo apt remove -y python-netaddr
2018-07-12 16:41:30.304180 | sudo: unable to resolve host devstack-xenial-eseries-fcp-provider-59-fcp-156580
2018-07-12 16:41:30.314075 | 
2018-07-12 16:41:30.314133 | WARNING: apt does not have a stable CLI interface. Use with caution in scripts.
2018-07-12 16:41:30.314143 | 
2018-07-12 16:41:30.342676 | Reading package lists...
2018-07-12 16:41:30.481453 | Building dependency tree...
2018-07-12 16:41:30.481890 | Reading state information...
2018-07-12 16:41:30.574427 | The following packages were automatically installed and are no longer required:
2018-07-12 16:41:30.574876 |   ieee-data linux-headers-4.4.0-66 snap-confine
2018-07-12 16:41:30.574935 | Use 'sudo apt autoremove' to remove them.
2018-07-12 16:41:30.575843 | The following packages will be REMOVED:
2018-07-12 16:41:30.575902 |   python-netaddr
2018-07-12 16:41:30.700080 | 0 upgraded, 0 newly installed, 1 to remove and 0 not upgraded.
2018-07-12 16:41:30.700161 | After this operation, 939 kB disk space will be freed.
2018-07-12 16:41:30.824336 | (Reading database ... 
(Reading database ... 5%
(Reading database ... 10%
(Reading database ... 15%
(Reading database ... 20%
(Reading database ... 25%
(Reading database ... 30%
(Reading database ... 35%
(Reading database ... 40%
(Reading database ... 45%
(Reading database ... 50%
(Reading database ... 55%
(Reading database ... 60%
(Reading database ... 65%
(Reading database ... 70%
(Reading database ... 75%
(Reading database ... 80%
(Reading database ... 85%
(Reading database ... 90%
(Reading database ... 95%
(Reading database ... 100%
(Reading database ... 128278 files and directories currently installed.)
2018-07-12 16:41:30.829565 | Removing python-netaddr (0.7.18-1) ...
2018-07-12 16:41:31.696841 | Processing triggers for man-db (2.7.5-1) ...
2018-07-12 16:41:33.889074 | + sudo apt remove -y python-enum34
2018-07-12 16:41:33.892375 | sudo: unable to resolve host devstack-xenial-eseries-fcp-provider-59-fcp-156580
2018-07-12 16:41:33.897199 | 
2018-07-12 16:41:33.897299 | WARNING: apt does not have a stable CLI interface. Use with caution in scripts.
2018-07-12 16:41:33.897321 | 
2018-07-12 16:41:33.922352 | Reading package lists...
2018-07-12 16:41:34.086120 | Building dependency tree...
2018-07-12 16:41:34.086709 | Reading state information...
2018-07-12 16:41:34.196567 | The following packages were automatically installed and are no longer required:
2018-07-12 16:41:34.196993 |   ieee-data linux-headers-4.4.0-66 python-cffi-backend python-idna
2018-07-12 16:41:34.197150 |   python-ipaddress snap-confine
2018-07-12 16:41:34.197203 | Use 'sudo apt autoremove' to remove them.
2018-07-12 16:41:34.198213 | The following packages will be REMOVED:
2018-07-12 16:41:34.198372 |   python-cryptography python-enum34 python-ndg-httpsclient python-openssl
2018-07-12 16:41:34.327191 | 0 upgraded, 0 newly installed, 4 to remove and 0 not upgraded.
2018-07-12 16:41:34.327268 | After this operation, 2,318 kB disk space will be freed.
2018-07-12 16:41:34.554535 | (Reading database ... 
(Reading database ... 5%
(Reading database ... 10%
(Reading database ... 15%
(Reading database ... 20%
(Reading database ... 25%
(Reading database ... 30%
(Reading database ... 35%
(Reading database ... 40%
(Reading database ... 45%
(Reading database ... 50%
(Reading database ... 55%
(Reading database ... 60%
(Reading database ... 65%
(Reading database ... 70%
(Reading database ... 75%
(Reading database ... 80%
(Reading database ... 85%
(Reading database ... 90%
(Reading database ... 95%
(Reading database ... 100%
(Reading database ... 128242 files and directories currently installed.)
2018-07-12 16:41:34.559849 | Removing python-ndg-httpsclient (0.4.0-3) ...
2018-07-12 16:41:35.550649 | Removing python-openssl (0.15.1-2build1) ...
2018-07-12 16:41:36.309736 | Removing python-cryptography (1.2.3-1ubuntu0.1) ...
2018-07-12 16:41:36.961192 | Removing python-enum34 (1.1.2-1) ...
2018-07-12 16:41:37.570606 | Processing triggers for man-db (2.7.5-1) ...
2018-07-12 16:41:38.969283 | + cat
2018-07-12 16:41:38.970461 | + /usr/zuul-env/bin/zuul-cloner -m clonemap.yaml --cache-dir /opt/git git://git.openstack.org openstack-infra/devstack-gate
2018-07-12 16:41:39.738121 | INFO:zuul.Cloner:Loaded map containing 1 rules
2018-07-12 16:41:39.738234 | INFO:zuul.CloneMapper:Workspace path set to: /home/jenkins/workspace/cinder-eseries-FCP
2018-07-12 16:41:39.738426 | INFO:zuul.CloneMapper:Mapping projects to workspace...
2018-07-12 16:41:39.738521 | INFO:zuul.CloneMapper:  openstack-infra/devstack-gate -> /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate
2018-07-12 16:41:39.738556 | INFO:zuul.CloneMapper:Expansion completed.
2018-07-12 16:41:39.738589 | INFO:zuul.Cloner:Preparing 1 repositories
2018-07-12 16:41:39.741902 | INFO:zuul.Cloner:Creating repo openstack-infra/devstack-gate from upstream git://git.openstack.org/openstack-infra/devstack-gate
2018-07-12 16:41:41.687007 | INFO:zuul.Cloner:upstream repo has branch master
2018-07-12 16:41:42.090463 | INFO:zuul.Cloner:Falling back to branch master
2018-07-12 16:41:42.102234 | INFO:zuul.Cloner:Prepared openstack-infra/devstack-gate repo with branch master at commit f93a3171ff80dfa4e6d67d6ce0c38c5e5f084e81
2018-07-12 16:41:42.102497 | INFO:zuul.Cloner:Prepared all repositories
2018-07-12 16:41:42.135172 | [Zuul] Task exit code: 0
2018-07-12 16:41:42.797862 | + export PYTHONUNBUFFERED=true
2018-07-12 16:41:42.797936 | + PYTHONUNBUFFERED=true
2018-07-12 16:41:42.797962 | + export BUILD_TIMEOUT=14400000
2018-07-12 16:41:42.797981 | + BUILD_TIMEOUT=14400000
2018-07-12 16:41:42.798004 | + export DEVSTACK_GATE_TEMPEST=1
2018-07-12 16:41:42.798023 | + DEVSTACK_GATE_TEMPEST=1
2018-07-12 16:41:42.798047 | + export DEVSTACK_GATE_TEMPEST_ALL=1
2018-07-12 16:41:42.798068 | + DEVSTACK_GATE_TEMPEST_ALL=1
2018-07-12 16:41:42.798139 | + export 'DEVSTACK_GATE_TEMPEST_REGEX=tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume))'
2018-07-12 16:41:42.798209 | + DEVSTACK_GATE_TEMPEST_REGEX='tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume))'
2018-07-12 16:41:42.798242 | + '[' eseries == eseries ']'
2018-07-12 16:41:42.798314 | + export 'DEVSTACK_GATE_TEMPEST_REGEX=tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume|test_groups))'
2018-07-12 16:41:42.798386 | + DEVSTACK_GATE_TEMPEST_REGEX='tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume|test_groups))'
2018-07-12 16:41:42.798416 | + export ATTACH_ENCRYPTED_VOLUME_AVAILABLE=False
2018-07-12 16:41:42.798472 | + ATTACH_ENCRYPTED_VOLUME_AVAILABLE=False
2018-07-12 16:41:42.798516 | + export TEMPEST_VOLUME_MANAGE_SNAPSHOT=False
2018-07-12 16:41:42.798543 | + TEMPEST_VOLUME_MANAGE_SNAPSHOT=False
2018-07-12 16:41:42.798559 | + export FORCE=yes
2018-07-12 16:41:42.798572 | + FORCE=yes
2018-07-12 16:41:42.798594 | + export TEMPEST_CONCURRENCY=1
2018-07-12 16:41:42.798613 | + TEMPEST_CONCURRENCY=1
2018-07-12 16:41:42.798634 | + export KEEP_LOCALRC=true
2018-07-12 16:41:42.798650 | + KEEP_LOCALRC=true
2018-07-12 16:41:42.798672 | + export OS_TEST_TIMEOUT=1800
2018-07-12 16:41:42.798690 | + OS_TEST_TIMEOUT=1800
2018-07-12 16:41:42.798714 | + export BRANCH_OVERRIDE=default
2018-07-12 16:41:42.798733 | + BRANCH_OVERRIDE=default
2018-07-12 16:41:42.798757 | + '[' default '!=' default ']'
2018-07-12 16:41:42.798777 | + export -f pre_test_hook
2018-07-12 16:41:42.798807 | + export -f post_test_hook
2018-07-12 16:41:42.798856 | + export OVERRIDE_ENABLED_SERVICES=c-api,c-bak,c-sch,c-vol,cinder,
2018-07-12 16:41:42.798901 | + OVERRIDE_ENABLED_SERVICES=c-api,c-bak,c-sch,c-vol,cinder,
2018-07-12 16:41:42.798960 | + export OVERRIDE_ENABLED_SERVICES+=dstat,g-api,g-reg,key,mysql,
2018-07-12 16:41:42.798992 | + OVERRIDE_ENABLED_SERVICES+=dstat,g-api,g-reg,key,mysql,
2018-07-12 16:41:42.799031 | + export OVERRIDE_ENABLED_SERVICES+=n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,
2018-07-12 16:41:42.799067 | + OVERRIDE_ENABLED_SERVICES+=n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,
2018-07-12 16:41:42.799096 | + export OVERRIDE_ENABLED_SERVICES+=rabbit,tempest,
2018-07-12 16:41:42.799122 | + OVERRIDE_ENABLED_SERVICES+=rabbit,tempest,
2018-07-12 16:41:42.799162 | + export OVERRIDE_ENABLED_SERVICES+=s-account,s-container,s-object,s-proxy
2018-07-12 16:41:42.799198 | + OVERRIDE_ENABLED_SERVICES+=s-account,s-container,s-object,s-proxy
2018-07-12 16:41:42.799223 | + [[ master =~ ^stable/(mitaka|newton)$ ]]
2018-07-12 16:41:42.799300 | + export OVERRIDE_ENABLED_SERVICES+=,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client
2018-07-12 16:41:42.799361 | + OVERRIDE_ENABLED_SERVICES+=,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client
2018-07-12 16:41:42.799400 | + cp devstack-gate/devstack-vm-gate-wrap.sh ./safe-devstack-vm-gate-wrap.sh
2018-07-12 16:41:42.800579 | + ./safe-devstack-vm-gate-wrap.sh
2018-07-12 16:41:42.806599 | apt-get is /usr/bin/apt-get
2018-07-12 16:41:42.812191 | sudo: unable to resolve host devstack-xenial-eseries-fcp-provider-59-fcp-156580
2018-07-12 16:41:43.036642 | sudo: unable to resolve host devstack-xenial-eseries-fcp-provider-59-fcp-156580
2018-07-12 16:41:43.037258 | sudo: /usr/sbin/ntpdate: command not found
2018-07-12 16:41:43.039631 | sudo: unable to resolve host devstack-xenial-eseries-fcp-provider-59-fcp-156580
2018-07-12 16:41:44.198419 | The PROJECTS list is:
2018-07-12 16:41:44.206308 | openstack/ceilometer openstack/ceilometermiddleware openstack/cinder 
2018-07-12 16:41:44.206370 | openstack-dev/devstack openstack/glance openstack/glance_store openstack/heat 
2018-07-12 16:41:44.206428 | openstack/heat-cfntools openstack/heat-templates openstack-infra/devstack-gate 
2018-07-12 16:41:44.206499 | openstack-infra/tripleo-ci openstack/keystone openstack/keystoneauth 
2018-07-12 16:41:44.206537 | openstack/keystonemiddleware openstack/manila openstack/neutron 
2018-07-12 16:41:44.206576 | openstack/neutron-fwaas openstack/neutron-lbaas openstack/neutron-vpnaas 
2018-07-12 16:41:44.206617 | openstack/nova openstack/octavia openstack/os-apply-config openstack/os-brick 
2018-07-12 16:41:44.206656 | openstack/osc-lib openstack/os-client-config openstack/os-collect-config 
2018-07-12 16:41:44.206696 | openstack/os-net-config openstack/os-refresh-config openstack/requirements 
2018-07-12 16:41:44.206734 | openstack/swift openstack/tempest openstack/tripleo-heat-templates 
2018-07-12 16:41:44.206776 | openstack/tripleo-image-elements openstack/zaqar
2018-07-12 16:41:44.206795 | ---
2018-07-12 16:41:44.217717 | Triggered by: https://review.openstack.org/572759 patchset 7
2018-07-12 16:41:44.217770 | Pipeline: upstream-eseries-check
2018-07-12 16:41:44.217810 | Timeout set to 230 minutes with 10 minutes reserved for cleanup.
2018-07-12 16:41:44.217833 | Available disk space on this host:
2018-07-12 16:41:44.223432 |     Filesystem      Size  Used Avail Use% Mounted on
2018-07-12 16:41:44.223550 |     udev            3.4G     0  3.4G   0% /dev
2018-07-12 16:41:44.223642 |     tmpfs           698M  664K  697M   1% /run
2018-07-12 16:41:44.223747 |     /dev/vda1        78G  4.0G   74G   6% /
2018-07-12 16:41:44.223837 |     tmpfs           3.5G     0  3.5G   0% /dev/shm
2018-07-12 16:41:44.223911 |     tmpfs           5.0M     0  5.0M   0% /run/lock
2018-07-12 16:41:44.224002 |     tmpfs           3.5G     0  3.5G   0% /sys/fs/cgroup
2018-07-12 16:41:44.224093 |     tmpfs           698M     0  698M   0% /run/user/1001
2018-07-12 16:41:44.227209 | sudo: unable to resolve host devstack-xenial-eseries-fcp-provider-59-fcp-156580
2018-07-12 16:41:44.998624 | Requirement already satisfied: virtualenv in /usr/local/lib/python2.7/dist-packages (16.0.0)
2018-07-12 16:41:45.147127 | New python executable in /tmp/ansible/bin/python
2018-07-12 16:41:47.602971 | Installing setuptools, pip, wheel...done.
2018-07-12 16:41:47.878136 | Collecting pbr
2018-07-12 16:41:48.015512 |   Downloading https://files.pythonhosted.org/packages/ae/d6/2ab389a3bf5fffd03069dacaddb0cdd531594abab5119f308527c0df53e6/pbr-4.1.0-py2.py3-none-any.whl (98kB)
2018-07-12 16:41:48.070175 | Installing collected packages: pbr
2018-07-12 16:41:48.116833 | Successfully installed pbr-4.1.0
2018-07-12 16:41:48.408068 | Collecting ansible==2.3.2.0
2018-07-12 16:41:48.552425 |   Downloading https://files.pythonhosted.org/packages/21/dc/ad51ca12ec4f7516d0befbc14312930a484a066b22192dac9c3814e349c4/ansible-2.3.2.0.tar.gz (4.3MB)
2018-07-12 16:41:50.719015 | Collecting devstack-tools==0.4.0
2018-07-12 16:41:50.748134 |   Downloading https://files.pythonhosted.org/packages/09/6a/0fee0d0bee19bf2fe2f242986ba4f97fdd4207bbd844ac142e94d828cd9a/devstack_tools-0.4.0-py2-none-any.whl
2018-07-12 16:41:50.763853 | Collecting ara
2018-07-12 16:41:50.807677 |   Downloading https://files.pythonhosted.org/packages/98/77/34bd5dfcc487da8832052094cfc0d08c69043d8cedd24dd0a3b83173ea9f/ara-0.15.0-py2.py3-none-any.whl (151kB)
2018-07-12 16:41:50.870274 | Collecting cmd2<0.9.0
2018-07-12 16:41:50.939457 |   Downloading https://files.pythonhosted.org/packages/f9/6a/0fc7efe26074a214b3b4d26a5a48d54a3c3919b440d5606c99021ed00c44/cmd2-0.8.8-py2.py3-none-any.whl (51kB)
2018-07-12 16:41:50.965311 | Collecting jinja2 (from ansible==2.3.2.0)
2018-07-12 16:41:51.003577 |   Downloading https://files.pythonhosted.org/packages/7f/ff/ae64bacdfc95f27a016a7bed8e8686763ba4d277a78ca76f32659220a731/Jinja2-2.10-py2.py3-none-any.whl (126kB)
2018-07-12 16:41:51.033680 | Collecting PyYAML (from ansible==2.3.2.0)
2018-07-12 16:41:51.074836 |   Downloading https://files.pythonhosted.org/packages/9e/a3/1d13970c3f36777c583f136c136f804d70f500168edc1edea6daa7200769/PyYAML-3.13.tar.gz (270kB)
2018-07-12 16:41:51.544891 | Collecting paramiko (from ansible==2.3.2.0)
2018-07-12 16:41:51.619741 |   Downloading https://files.pythonhosted.org/packages/3e/db/cb7b6656e0e7387637ce850689084dc0b94b44df31cc52e5fc5c2c4fd2c1/paramiko-2.4.1-py2.py3-none-any.whl (194kB)
2018-07-12 16:41:51.659635 | Collecting pycrypto>=2.6 (from ansible==2.3.2.0)
2018-07-12 16:41:51.685354 |   Downloading https://files.pythonhosted.org/packages/60/db/645aa9af249f059cc3a368b118de33889219e0362141e75d4eaf6f80f163/pycrypto-2.6.1.tar.gz (446kB)
2018-07-12 16:41:51.963213 | Requirement already satisfied: setuptools in /tmp/ansible/lib/python2.7/site-packages (from ansible==2.3.2.0) (40.0.0)
2018-07-12 16:41:51.968402 | Requirement already satisfied: pbr>=1.8 in /tmp/ansible/lib/python2.7/site-packages (from devstack-tools==0.4.0) (4.1.0)
2018-07-12 16:41:51.974222 | Collecting XStatic-DataTables>=1.10.15 (from ara)
2018-07-12 16:41:51.999946 |   Downloading https://files.pythonhosted.org/packages/3c/bb/d6a58cd1c4082bb5824db4eacb9293a882037793f41bef7bcaabc34ff9dd/XStatic-DataTables-1.10.15.1.tar.gz (209kB)
2018-07-12 16:41:52.206659 | Collecting python-subunit (from ara)
2018-07-12 16:41:52.236762 |   Downloading https://files.pythonhosted.org/packages/ee/3a/b8a93e1f5b9a9f7e0a7630146f1c62878b6949ac5e4bac6ae2ae13fa9f83/python_subunit-1.3.0-py2.py3-none-any.whl (104kB)
2018-07-12 16:41:52.270026 | Collecting XStatic-Patternfly>=3.21.0 (from ara)
2018-07-12 16:41:52.292927 |   Downloading https://files.pythonhosted.org/packages/4c/1e/3f69523bf8c2ff8d28d62d87237389ecea32471ab70408d34d14c4c4cb3d/XStatic-Patternfly-3.21.0.1.tar.gz (5.7MB)
2018-07-12 16:41:53.209229 | Collecting oslo.utils>=3.20.0 (from ara)
2018-07-12 16:41:53.282292 |   Downloading https://files.pythonhosted.org/packages/e8/6c/fa156d4487a388b1b170c42d49bb6576f99fa5566400e238c0850c6a1be1/oslo.utils-3.36.3-py2.py3-none-any.whl (91kB)
2018-07-12 16:41:53.317162 | Collecting decorator>=4.0.0 (from ara)
2018-07-12 16:41:53.351223 |   Downloading https://files.pythonhosted.org/packages/bc/bb/a24838832ba35baf52f32ab1a49b906b5f82fb7c76b2f6a7e35e140bac30/decorator-4.3.0-py2.py3-none-any.whl
2018-07-12 16:41:53.364329 | Collecting pygments>=1.6 (from ara)
2018-07-12 16:41:53.413363 |   Downloading https://files.pythonhosted.org/packages/02/ee/b6e02dc6529e82b75bb06823ff7d005b141037cb1416b10c6f00fc419dca/Pygments-2.2.0-py2.py3-none-any.whl (841kB)
2018-07-12 16:41:53.514807 | Collecting junit-xml>=1.7 (from ara)
2018-07-12 16:41:53.539825 |   Downloading https://files.pythonhosted.org/packages/a6/2a/f8d5aab80bb31fcc789d0f2b34b49f08bd6121cd8798d2e37f416df2b9f8/junit-xml-1.8.tar.gz
2018-07-12 16:41:53.711273 | Collecting Flask-SQLAlchemy (from ara)
2018-07-12 16:41:53.741681 |   Downloading https://files.pythonhosted.org/packages/a1/44/294fb7f6bf49cc7224417cd0637018db9fee0729b4fe166e43e2bbb1f1c8/Flask_SQLAlchemy-2.3.2-py2.py3-none-any.whl
2018-07-12 16:41:53.756283 | Collecting pyfakefs (from ara)
2018-07-12 16:41:53.785316 |   Downloading https://files.pythonhosted.org/packages/30/33/606714ea818a3847f7ef5c3f6e4d7a2221491ecdfe267282d1c7a1f1e605/pyfakefs-3.4.3-py2.py3-none-any.whl (153kB)
2018-07-12 16:41:53.812804 | Collecting six (from ara)
2018-07-12 16:41:53.845478 |   Downloading https://files.pythonhosted.org/packages/67/4b/141a581104b1f6397bfa78ac9d43d8ad29a7ca43ea90a2d863fe3056e86a/six-1.11.0-py2.py3-none-any.whl
2018-07-12 16:41:53.858008 | Collecting Flask-Migrate (from ara)
2018-07-12 16:41:53.888541 |   Downloading https://files.pythonhosted.org/packages/59/97/f681c9e43d2e2ace4881fa588d847cc25f47cc98f7400e237805d20d6f79/Flask_Migrate-2.2.1-py2.py3-none-any.whl
2018-07-12 16:41:53.905732 | Collecting Flask!=0.12.3,<0.13,>=0.11 (from ara)
2018-07-12 16:41:53.943106 |   Downloading https://files.pythonhosted.org/packages/2e/48/f1936dadac2326b3d73f2fe0a964a87d16be16eb9d7fc56f09c1bea3d17c/Flask-0.12.4-py2.py3-none-any.whl (81kB)
2018-07-12 16:41:53.966396 | Collecting Frozen-Flask (from ara)
2018-07-12 16:41:53.995474 |   Downloading https://files.pythonhosted.org/packages/94/f7/d04d4ee76a9ceb4c1dc1846e86d8784b72e38179fd5f468b61e77bb52296/Frozen_Flask-0.15-py2.py3-none-any.whl
2018-07-12 16:41:54.009788 | Collecting XStatic>=1.0.0 (from ara)
2018-07-12 16:41:54.032972 |   Downloading https://files.pythonhosted.org/packages/3e/30/726b61d07abd031b32db956adfbcf8924687e07879c1b63b777855c75289/XStatic-1.0.1.tar.gz
2018-07-12 16:41:54.197161 | Collecting Flask-Script (from ara)
2018-07-12 16:41:54.227572 |   Downloading https://files.pythonhosted.org/packages/00/a4/cd587b2b19f043b65bf33ceda2f6e4e6cdbd0ce18d01a52b9559781b1da6/Flask-Script-2.0.6.tar.gz (43kB)
2018-07-12 16:41:54.434577 | Collecting XStatic-jQuery>=1.8.2.1 (from ara)
2018-07-12 16:41:54.464046 |   Downloading https://files.pythonhosted.org/packages/f4/f3/b806d039ec4cd3ff601d7af49a18cb70697171c7b93030d4f1ffb881c174/XStatic-jQuery-1.10.2.1.tar.gz (116kB)
2018-07-12 16:41:54.659967 | Collecting cliff (from ara)
2018-07-12 16:41:54.711770 |   Downloading https://files.pythonhosted.org/packages/06/6d/672b0f1eb3c5f455dff6e9558990c3b0777c70452b8020b62c425035795c/cliff-2.13.0-py2.py3-none-any.whl (71kB)
2018-07-12 16:41:54.745080 | Collecting XStatic-Patternfly-Bootstrap-Treeview>=2.1.3 (from ara)
2018-07-12 16:41:54.768364 |   Downloading https://files.pythonhosted.org/packages/3a/ec/c69056a3516127e511cf102a3590b226c5f4c0199b6bf351bcc6c468bdf0/XStatic-Patternfly-Bootstrap-Treeview-2.1.3.2.tar.gz
2018-07-12 16:41:54.955749 | Collecting debtcollector>=1.2.0 (from ara)
2018-07-12 16:41:54.998656 |   Downloading https://files.pythonhosted.org/packages/77/19/d9c7797fd0916a57a76bd65febb2e08871faaa728cda6a21d5889de1c566/debtcollector-1.19.0-py2.py3-none-any.whl
2018-07-12 16:41:55.019174 | Collecting XStatic-Bootstrap-SCSS>=3.3.7.1 (from ara)
2018-07-12 16:41:55.046174 |   Downloading https://files.pythonhosted.org/packages/c6/8c/4a4784d08dd01afe198ef1a8c7c8104d4c5f638257769747ca29bf1e671a/XStatic_Bootstrap_SCSS-3.3.7.1-py2.py3-none-any.whl (247kB)
2018-07-12 16:41:55.084118 | Collecting oslo.serialization>=1.10.0 (from ara)
2018-07-12 16:41:55.140075 |   Downloading https://files.pythonhosted.org/packages/b6/77/5d322fb625f0db2bcca035ff6ff1906c718b31cd371bcf25bc31f7c2075d/oslo.serialization-2.27.0-py2.py3-none-any.whl
2018-07-12 16:41:55.159646 | Collecting pyperclip (from cmd2<0.9.0)
2018-07-12 16:41:55.191934 |   Downloading https://files.pythonhosted.org/packages/33/15/f3c29b381815ae75e27589583655f4a8567721c541b8ba8cd52f76868655/pyperclip-1.6.2.tar.gz
2018-07-12 16:41:55.360189 | Collecting contextlib2; python_version < "3.5" (from cmd2<0.9.0)
2018-07-12 16:41:55.389036 |   Downloading https://files.pythonhosted.org/packages/a2/71/8273a7eeed0aff6a854237ab5453bc9aa67deb49df4832801c21f0ff3782/contextlib2-0.5.5-py2.py3-none-any.whl
2018-07-12 16:41:55.402548 | Collecting pyparsing>=2.0.1 (from cmd2<0.9.0)
2018-07-12 16:41:55.478232 |   Downloading https://files.pythonhosted.org/packages/6a/8a/718fd7d3458f9fab8e67186b00abdd345b639976bc7fb3ae722e1b026a50/pyparsing-2.2.0-py2.py3-none-any.whl (56kB)
2018-07-12 16:41:55.494436 | Collecting enum34; python_version < "3.4" (from cmd2<0.9.0)
2018-07-12 16:41:55.531187 |   Downloading https://files.pythonhosted.org/packages/c5/db/e56e6b4bbac7c4a06de1c50de6fe1ef3810018ae11732a50f15f62c7d050/enum34-1.1.6-py2-none-any.whl
2018-07-12 16:41:55.545361 | Collecting wcwidth; sys_platform != "win32" (from cmd2<0.9.0)
2018-07-12 16:41:55.571901 |   Downloading https://files.pythonhosted.org/packages/7e/9f/526a6947247599b084ee5232e4f9190a38f398d7300d866af3ab571a5bfe/wcwidth-0.1.7-py2.py3-none-any.whl
2018-07-12 16:41:55.586703 | Collecting subprocess32; python_version < "3.0" (from cmd2<0.9.0)
2018-07-12 16:41:55.616177 |   Downloading https://files.pythonhosted.org/packages/c3/5f/7117737fc7114061837a4f51670d863dd7f7f9c762a6546fa8a0dcfe61c8/subprocess32-3.5.2.tar.gz (96kB)
2018-07-12 16:41:55.803091 | Collecting MarkupSafe>=0.23 (from jinja2->ansible==2.3.2.0)
2018-07-12 16:41:55.834234 |   Downloading https://files.pythonhosted.org/packages/4d/de/32d741db316d8fdb7680822dd37001ef7a448255de9699ab4bfcbdf4172b/MarkupSafe-1.0.tar.gz
2018-07-12 16:41:56.006629 | Collecting pyasn1>=0.1.7 (from paramiko->ansible==2.3.2.0)
2018-07-12 16:41:56.090714 |   Downloading https://files.pythonhosted.org/packages/a0/70/2c27740f08e477499ce19eefe05dbcae6f19fdc49e9e82ce4768be0643b9/pyasn1-0.4.3-py2.py3-none-any.whl (72kB)
2018-07-12 16:41:56.111397 | Collecting bcrypt>=3.1.3 (from paramiko->ansible==2.3.2.0)
2018-07-12 16:41:56.189254 |   Downloading https://files.pythonhosted.org/packages/2e/5a/2abeae20ce294fe6bf63da0e0b5a885c788e1360bbd124edcc0429678a59/bcrypt-3.1.4-cp27-cp27mu-manylinux1_x86_64.whl (57kB)
2018-07-12 16:41:56.208168 | Collecting cryptography>=1.5 (from paramiko->ansible==2.3.2.0)
2018-07-12 16:41:56.525960 |   Downloading https://files.pythonhosted.org/packages/dd/c2/3a5bfefb25690725824ade71e6b65449f0a9f4b29702cce10560f786ebf6/cryptography-2.2.2-cp27-cp27mu-manylinux1_x86_64.whl (2.2MB)
2018-07-12 16:41:56.716290 | Collecting pynacl>=1.0.1 (from paramiko->ansible==2.3.2.0)
2018-07-12 16:41:56.769045 |   Downloading https://files.pythonhosted.org/packages/80/3d/d709b9fbd69e21dd3a4d34eb690c5484094699e03b7447bc7eb173cfd7b6/PyNaCl-1.2.1-cp27-cp27mu-manylinux1_x86_64.whl (696kB)
2018-07-12 16:41:56.901267 | Collecting testtools>=0.9.34 (from python-subunit->ara)
2018-07-12 16:41:56.944523 |   Downloading https://files.pythonhosted.org/packages/87/74/a4d55da28d7bba6d6f49430f22a62afd8472cb24a63fa61daef80d3e821b/testtools-2.3.0-py2.py3-none-any.whl (184kB)
2018-07-12 16:41:56.986108 | Collecting extras (from python-subunit->ara)
2018-07-12 16:41:57.009541 |   Downloading https://files.pythonhosted.org/packages/03/e9/e915af1f97914cd0bc021e125fd1bfd4106de614a275e4b6866dd9a209ac/extras-1.0.0-py2.py3-none-any.whl
2018-07-12 16:41:57.021226 | Collecting pytz>=2013.6 (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.210033 |   Downloading https://files.pythonhosted.org/packages/30/4e/27c34b62430286c6d59177a0842ed90dc789ce5d1ed740887653b898779a/pytz-2018.5-py2.py3-none-any.whl (510kB)
2018-07-12 16:41:57.319782 | Collecting iso8601>=0.1.11 (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.350564 |   Downloading https://files.pythonhosted.org/packages/ef/57/7162609dab394d38bbc7077b7ba0a6f10fb09d8b7701ea56fa1edc0c4345/iso8601-0.1.12-py2.py3-none-any.whl
2018-07-12 16:41:57.365802 | Collecting funcsigs>=1.0.0; python_version == "2.7" or python_version == "2.6" (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.390771 |   Downloading https://files.pythonhosted.org/packages/69/cb/f5be453359271714c01b9bd06126eaf2e368f1fddfff30818754b5ac2328/funcsigs-1.0.2-py2.py3-none-any.whl
2018-07-12 16:41:57.407773 | Collecting oslo.i18n>=3.15.3 (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.458572 |   Downloading https://files.pythonhosted.org/packages/41/19/6bdc09c5548fae467f00120812256c27a253fa29d07020ecf725d3a247cb/oslo.i18n-3.20.0-py2.py3-none-any.whl (42kB)
2018-07-12 16:41:57.482817 | Collecting netifaces>=0.10.4 (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.530543 |   Downloading https://files.pythonhosted.org/packages/70/dd/411bb4cda549136cf9ff5dbd4f33f898fd90b25ac73fd4ea42a3d3e8fd15/netifaces-0.10.7-cp27-cp27mu-manylinux1_x86_64.whl
2018-07-12 16:41:57.545646 | Collecting netaddr>=0.7.18 (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.610670 |   Downloading https://files.pythonhosted.org/packages/ba/97/ce14451a9fd7bdb5a397abf99b24a1a6bb7a1a440b019bebd2e9a0dbec74/netaddr-0.7.19-py2.py3-none-any.whl (1.6MB)
2018-07-12 16:41:57.762547 | Collecting monotonic>=0.6 (from oslo.utils>=3.20.0->ara)
2018-07-12 16:41:57.790599 |   Downloading https://files.pythonhosted.org/packages/ac/aa/063eca6a416f397bd99552c534c6d11d57f58f2e94c14780f3bbf818c4cf/monotonic-1.5-py2.py3-none-any.whl
2018-07-12 16:41:58.747484 | Collecting SQLAlchemy>=0.8.0 (from Flask-SQLAlchemy->ara)
2018-07-12 16:41:58.819528 |   Downloading https://files.pythonhosted.org/packages/28/99/ad4dd8240ff8a98c8786fef6d2b392fb2309b0c2bcf23fdfbf3a4cb1a499/SQLAlchemy-1.2.9.tar.gz (5.6MB)
2018-07-12 16:42:00.025529 | Collecting alembic>=0.7 (from Flask-Migrate->ara)
2018-07-12 16:42:00.093254 |   Downloading https://files.pythonhosted.org/packages/98/dd/fce24f825880875f073c0f9169a9e629ae1d9ea722ebb944153a0b68ab46/alembic-0.9.10.tar.gz (1.0MB)
2018-07-12 16:42:00.455225 | Collecting Werkzeug>=0.7 (from Flask!=0.12.3,<0.13,>=0.11->ara)
2018-07-12 16:42:00.505580 |   Downloading https://files.pythonhosted.org/packages/20/c4/12e3e56473e52375aa29c4764e70d1b8f3efa6682bef8d0aae04fe335243/Werkzeug-0.14.1-py2.py3-none-any.whl (322kB)
2018-07-12 16:42:00.546023 | Collecting click>=2.0 (from Flask!=0.12.3,<0.13,>=0.11->ara)
2018-07-12 16:42:00.588070 |   Downloading https://files.pythonhosted.org/packages/34/c1/8806f99713ddb993c5366c362b2f908f18269f8d792aff1abfd700775a77/click-6.7-py2.py3-none-any.whl (71kB)
2018-07-12 16:42:00.603370 | Collecting itsdangerous>=0.21 (from Flask!=0.12.3,<0.13,>=0.11->ara)
2018-07-12 16:42:00.628267 |   Downloading https://files.pythonhosted.org/packages/dc/b4/a60bcdba945c00f6d608d8975131ab3f25b22f2bcfe1dab221165194b2d4/itsdangerous-0.24.tar.gz (46kB)
2018-07-12 16:42:00.782433 | Collecting stevedore>=1.20.0 (from cliff->ara)
2018-07-12 16:42:00.831137 |   Downloading https://files.pythonhosted.org/packages/17/6b/3b7d6d08b2ab3e5ef09e01c9f7b3b590ee135f289bb94553419e40922c25/stevedore-1.28.0-py2.py3-none-any.whl
2018-07-12 16:42:00.848992 | Collecting PrettyTable<0.8,>=0.7.2 (from cliff->ara)
2018-07-12 16:42:00.880233 |   Downloading https://files.pythonhosted.org/packages/ef/30/4b0746848746ed5941f052479e7c23d2b56d174b82f4fd34a25e389831f5/prettytable-0.7.2.tar.bz2
2018-07-12 16:42:01.054968 | Collecting unicodecsv>=0.8.0; python_version < "3.0" (from cliff->ara)
2018-07-12 16:42:01.081264 |   Downloading https://files.pythonhosted.org/packages/6f/a4/691ab63b17505a26096608cc309960b5a6bdf39e4ba1a793d5f9b1a53270/unicodecsv-0.14.1.tar.gz
2018-07-12 16:42:01.249164 | Collecting wrapt>=1.7.0 (from debtcollector>=1.2.0->ara)
2018-07-12 16:42:01.281854 |   Downloading https://files.pythonhosted.org/packages/a0/47/66897906448185fcb77fc3c2b1bc20ed0ecca81a0f2f88eda3fc5a34fc3d/wrapt-1.10.11.tar.gz
2018-07-12 16:42:01.431706 | Collecting msgpack>=0.5.2 (from oslo.serialization>=1.10.0->ara)
2018-07-12 16:42:01.485599 |   Downloading https://files.pythonhosted.org/packages/ff/0d/536fd0b2808dfbc67de46168dc706b5c9f9a1f5a803d96b8bc562a6d96c2/msgpack-0.5.6-cp27-cp27mu-manylinux1_x86_64.whl (295kB)
2018-07-12 16:42:01.558138 | Collecting cffi>=1.1 (from bcrypt>=3.1.3->paramiko->ansible==2.3.2.0)
2018-07-12 16:42:01.759060 |   Downloading https://files.pythonhosted.org/packages/14/dd/3e7a1e1280e7d767bd3fa15791759c91ec19058ebe31217fe66f3e9a8c49/cffi-1.11.5-cp27-cp27mu-manylinux1_x86_64.whl (407kB)
2018-07-12 16:42:01.800126 | Collecting asn1crypto>=0.21.0 (from cryptography>=1.5->paramiko->ansible==2.3.2.0)
2018-07-12 16:42:01.834892 |   Downloading https://files.pythonhosted.org/packages/ea/cd/35485615f45f30a510576f1a56d1e0a7ad7bd8ab5ed7cdc600ef7cd06222/asn1crypto-0.24.0-py2.py3-none-any.whl (101kB)
2018-07-12 16:42:01.854903 | Collecting idna>=2.1 (from cryptography>=1.5->paramiko->ansible==2.3.2.0)
2018-07-12 16:42:01.885488 |   Downloading https://files.pythonhosted.org/packages/4b/2a/0276479a4b3caeb8a8c1af2f8e4355746a97fab05a372e4a2c6a6b876165/idna-2.7-py2.py3-none-any.whl (58kB)
2018-07-12 16:42:01.901864 | Collecting ipaddress; python_version < "3" (from cryptography>=1.5->paramiko->ansible==2.3.2.0)
2018-07-12 16:42:01.934784 |   Downloading https://files.pythonhosted.org/packages/fc/d0/7fc3a811e011d4b388be48a0e381db8d990042df54aa4ef4599a31d39853/ipaddress-1.0.22-py2.py3-none-any.whl
2018-07-12 16:42:01.947612 | Collecting unittest2>=1.0.0 (from testtools>=0.9.34->python-subunit->ara)
2018-07-12 16:42:01.977694 |   Downloading https://files.pythonhosted.org/packages/72/20/7f0f433060a962200b7272b8c12ba90ef5b903e218174301d0abfd523813/unittest2-1.1.0-py2.py3-none-any.whl (96kB)
2018-07-12 16:42:01.999694 | Collecting traceback2 (from testtools>=0.9.34->python-subunit->ara)
2018-07-12 16:42:02.025308 |   Downloading https://files.pythonhosted.org/packages/17/0a/6ac05a3723017a967193456a2efa0aa9ac4b51456891af1e2353bb9de21e/traceback2-1.4.0-py2.py3-none-any.whl
2018-07-12 16:42:02.038431 | Collecting fixtures>=1.3.0 (from testtools>=0.9.34->python-subunit->ara)
2018-07-12 16:42:02.074033 |   Downloading https://files.pythonhosted.org/packages/a8/28/7eed6bf76792f418029a18d5b2ace87ce7562927cdd00f1cefe481cd148f/fixtures-3.0.0-py2.py3-none-any.whl (67kB)
2018-07-12 16:42:02.097970 | Collecting python-mimeparse (from testtools>=0.9.34->python-subunit->ara)
2018-07-12 16:42:02.122686 |   Downloading https://files.pythonhosted.org/packages/26/2e/03bce213a9bf02a2750dcb04e761785e9c763fc11071edc4b447eacbb842/python_mimeparse-1.6.0-py2.py3-none-any.whl
2018-07-12 16:42:02.136182 | Collecting Babel!=2.4.0,>=2.3.4 (from oslo.i18n>=3.15.3->oslo.utils>=3.20.0->ara)
2018-07-12 16:42:02.170728 |   Downloading https://files.pythonhosted.org/packages/b8/ad/c6f60602d3ee3d92fbed87675b6fb6a6f9a38c223343ababdb44ba201f10/Babel-2.6.0-py2.py3-none-any.whl (8.1MB)
2018-07-12 16:42:02.800301 | Collecting Mako (from alembic>=0.7->Flask-Migrate->ara)
2018-07-12 16:42:02.840074 |   Downloading https://files.pythonhosted.org/packages/eb/f3/67579bb486517c0d49547f9697e36582cd19dafb5df9e687ed8e22de57fa/Mako-1.0.7.tar.gz (564kB)
2018-07-12 16:42:03.120898 | Collecting python-editor>=0.3 (from alembic>=0.7->Flask-Migrate->ara)
2018-07-12 16:42:03.147668 |   Downloading https://files.pythonhosted.org/packages/65/1e/adf6e000ea5dc909aa420352d6ba37f16434c8a3c2fa030445411a1ed545/python-editor-1.0.3.tar.gz
2018-07-12 16:42:03.314179 | Collecting python-dateutil (from alembic>=0.7->Flask-Migrate->ara)
2018-07-12 16:42:03.356163 |   Downloading https://files.pythonhosted.org/packages/cf/f5/af2b09c957ace60dcfac112b669c45c8c97e32f94aa8b56da4c6d1682825/python_dateutil-2.7.3-py2.py3-none-any.whl (211kB)
2018-07-12 16:42:03.382157 | Collecting pycparser (from cffi>=1.1->bcrypt>=3.1.3->paramiko->ansible==2.3.2.0)
2018-07-12 16:42:03.409404 |   Downloading https://files.pythonhosted.org/packages/8c/2d/aad7f16146f4197a11f8e91fb81df177adcc2073d36a17b1491fd09df6ed/pycparser-2.18.tar.gz (245kB)
2018-07-12 16:42:03.622758 | Requirement already satisfied: argparse in /usr/lib/python2.7 (from unittest2>=1.0.0->testtools>=0.9.34->python-subunit->ara) (1.2.1)
2018-07-12 16:42:03.627617 | Collecting linecache2 (from traceback2->testtools>=0.9.34->python-subunit->ara)
2018-07-12 16:42:03.652555 |   Downloading https://files.pythonhosted.org/packages/c7/a3/c5da2a44c85bfbb6eebcfc1dde24933f8704441b98fdde6528f4831757a6/linecache2-1.0.0-py2.py3-none-any.whl
2018-07-12 16:42:03.663950 | Building wheels for collected packages: ansible, PyYAML, pycrypto, XStatic-DataTables, XStatic-Patternfly, junit-xml, XStatic, Flask-Script, XStatic-jQuery, XStatic-Patternfly-Bootstrap-Treeview, pyperclip, subprocess32, MarkupSafe, SQLAlchemy, alembic, itsdangerous, PrettyTable, unicodecsv, wrapt, Mako, python-editor, pycparser
2018-07-12 16:42:03.664270 |   Running setup.py bdist_wheel for ansible: started
2018-07-12 16:42:05.498668 |   Running setup.py bdist_wheel for ansible: finished with status 'done'
2018-07-12 16:42:05.500998 |   Stored in directory: /home/jenkins/.cache/pip/wheels/80/3d/51/80ece6d686c50a16914027c019d495ef1975bd0f8bb5bffa34
2018-07-12 16:42:05.908126 |   Running setup.py bdist_wheel for PyYAML: started
2018-07-12 16:42:06.329713 |   Running setup.py bdist_wheel for PyYAML: finished with status 'done'
2018-07-12 16:42:06.330058 |   Stored in directory: /home/jenkins/.cache/pip/wheels/ad/da/0c/74eb680767247273e2cf2723482cb9c924fe70af57c334513f
2018-07-12 16:42:06.348510 |   Running setup.py bdist_wheel for pycrypto: started
2018-07-12 16:42:14.465686 |   Running setup.py bdist_wheel for pycrypto: finished with status 'done'
2018-07-12 16:42:14.467979 |   Stored in directory: /home/jenkins/.cache/pip/wheels/27/02/5e/77a69d0c16bb63c6ed32f5386f33a2809c94bd5414a2f6c196
2018-07-12 16:42:14.507752 |   Running setup.py bdist_wheel for XStatic-DataTables: started
2018-07-12 16:42:14.743614 |   Running setup.py bdist_wheel for XStatic-DataTables: finished with status 'done'
2018-07-12 16:42:14.744095 |   Stored in directory: /home/jenkins/.cache/pip/wheels/8b/e7/19/94c86d8db95576f14dc10fec88499287406683a18a9f107400
2018-07-12 16:42:14.758982 |   Running setup.py bdist_wheel for XStatic-Patternfly: started
2018-07-12 16:42:15.824570 |   Running setup.py bdist_wheel for XStatic-Patternfly: finished with status 'done'
2018-07-12 16:42:15.825398 |   Stored in directory: /home/jenkins/.cache/pip/wheels/4c/b0/3e/d57d0ef0dfbdf6c2dd4164a3e4707427a5f096d01bf82099fb
2018-07-12 16:42:15.953974 |   Running setup.py bdist_wheel for junit-xml: started
2018-07-12 16:42:16.129695 |   Running setup.py bdist_wheel for junit-xml: finished with status 'done'
2018-07-12 16:42:16.130046 |   Stored in directory: /home/jenkins/.cache/pip/wheels/c6/c5/65/5b166afb6eac87dc300368ec4d92f39502dd41cdc73056d49e
2018-07-12 16:42:16.133811 |   Running setup.py bdist_wheel for XStatic: started
2018-07-12 16:42:16.305654 |   Running setup.py bdist_wheel for XStatic: finished with status 'done'
2018-07-12 16:42:16.306198 |   Stored in directory: /home/jenkins/.cache/pip/wheels/50/3c/4a/7c91cae8106ca9b88fad364e8d421e55e7db4d72f776429792
2018-07-12 16:42:16.311685 |   Running setup.py bdist_wheel for Flask-Script: started
2018-07-12 16:42:16.499710 |   Running setup.py bdist_wheel for Flask-Script: finished with status 'done'
2018-07-12 16:42:16.500002 |   Stored in directory: /home/jenkins/.cache/pip/wheels/1c/17/70/4598e6dba4bec58c1b59552c6409272aea31978ab8159f11a1
2018-07-12 16:42:16.582594 |   Running setup.py bdist_wheel for XStatic-jQuery: started
2018-07-12 16:42:16.787592 |   Running setup.py bdist_wheel for XStatic-jQuery: finished with status 'done'
2018-07-12 16:42:16.788128 |   Stored in directory: /home/jenkins/.cache/pip/wheels/0b/e8/db/08a273b9a4bbf2f471fccb71db2b4954e552b2563641de57c2
2018-07-12 16:42:16.905850 |   Running setup.py bdist_wheel for XStatic-Patternfly-Bootstrap-Treeview: started
2018-07-12 16:42:17.088803 |   Running setup.py bdist_wheel for XStatic-Patternfly-Bootstrap-Treeview: finished with status 'done'
2018-07-12 16:42:17.089120 |   Stored in directory: /home/jenkins/.cache/pip/wheels/d5/7b/4a/9b9f6033a880258e1614b9b6c3f6622377cc6e86cfceb6d54b
2018-07-12 16:42:17.094119 |   Running setup.py bdist_wheel for pyperclip: started
2018-07-12 16:42:17.257970 |   Running setup.py bdist_wheel for pyperclip: finished with status 'done'
2018-07-12 16:42:17.258262 |   Stored in directory: /home/jenkins/.cache/pip/wheels/58/32/92/2227fba72f0702e4168f084c6dfc2d6d3fd1904634ab61ca6a
2018-07-12 16:42:17.261842 |   Running setup.py bdist_wheel for subprocess32: started
2018-07-12 16:42:19.217346 |   Running setup.py bdist_wheel for subprocess32: finished with status 'done'
2018-07-12 16:42:19.217713 |   Stored in directory: /home/jenkins/.cache/pip/wheels/b1/a2/4d/25a65a64749cd589ffae2fdd1a7baa15a3986a8ea8af48feaf
2018-07-12 16:42:19.222411 |   Running setup.py bdist_wheel for MarkupSafe: started
2018-07-12 16:42:19.971673 |   Running setup.py bdist_wheel for MarkupSafe: finished with status 'done'
2018-07-12 16:42:19.972011 |   Stored in directory: /home/jenkins/.cache/pip/wheels/33/56/20/ebe49a5c612fffe1c5a632146b16596f9e64676768661e4e46
2018-07-12 16:42:19.976379 |   Running setup.py bdist_wheel for SQLAlchemy: started
2018-07-12 16:42:21.012499 |   Running setup.py bdist_wheel for SQLAlchemy: finished with status 'done'
2018-07-12 16:42:21.013236 |   Stored in directory: /home/jenkins/.cache/pip/wheels/f5/87/a1/ef324a6389f03b1edf1b7822413e5137ef831ded8a2fba5313
2018-07-12 16:42:21.086011 |   Running setup.py bdist_wheel for alembic: started
2018-07-12 16:42:21.335216 |   Running setup.py bdist_wheel for alembic: finished with status 'done'
2018-07-12 16:42:21.335591 |   Stored in directory: /home/jenkins/.cache/pip/wheels/5a/98/f9/4aecdd767cddcbee88474401b27f52bf31c809e0334d6942ae
2018-07-12 16:42:21.356275 |   Running setup.py bdist_wheel for itsdangerous: started
2018-07-12 16:42:21.578913 |   Running setup.py bdist_wheel for itsdangerous: finished with status 'done'
2018-07-12 16:42:21.579176 |   Stored in directory: /home/jenkins/.cache/pip/wheels/2c/4a/61/5599631c1554768c6290b08c02c72d7317910374ca602ff1e5
2018-07-12 16:42:21.664016 |   Running setup.py bdist_wheel for PrettyTable: started
2018-07-12 16:42:21.832907 |   Running setup.py bdist_wheel for PrettyTable: finished with status 'done'
2018-07-12 16:42:21.833171 |   Stored in directory: /home/jenkins/.cache/pip/wheels/80/34/1c/3967380d9676d162cb59513bd9dc862d0584e045a162095606
2018-07-12 16:42:21.848357 |   Running setup.py bdist_wheel for unicodecsv: started
2018-07-12 16:42:22.012060 |   Running setup.py bdist_wheel for unicodecsv: finished with status 'done'
2018-07-12 16:42:22.012380 |   Stored in directory: /home/jenkins/.cache/pip/wheels/a6/09/e9/e800279c98a0a8c94543f3de6c8a562f60e51363ed26e71283
2018-07-12 16:42:22.016276 |   Running setup.py bdist_wheel for wrapt: started
2018-07-12 16:42:22.728376 |   Running setup.py bdist_wheel for wrapt: finished with status 'done'
2018-07-12 16:42:22.728723 |   Stored in directory: /home/jenkins/.cache/pip/wheels/48/5d/04/22361a593e70d23b1f7746d932802efe1f0e523376a74f321e
2018-07-12 16:42:22.734267 |   Running setup.py bdist_wheel for Mako: started
2018-07-12 16:42:22.954311 |   Running setup.py bdist_wheel for Mako: finished with status 'done'
2018-07-12 16:42:22.954669 |   Stored in directory: /home/jenkins/.cache/pip/wheels/15/35/25/dbcb848832ccb1a4b4ad23f529badfd3bce9bf88017f7ca510
2018-07-12 16:42:22.965953 |   Running setup.py bdist_wheel for python-editor: started
2018-07-12 16:42:23.140313 |   Running setup.py bdist_wheel for python-editor: finished with status 'done'
2018-07-12 16:42:23.140674 |   Stored in directory: /home/jenkins/.cache/pip/wheels/36/e0/98/ba386b125a00ea9dd52e2c16aa2ec0adbbd639b84bfe2e001d
2018-07-12 16:42:23.143729 |   Running setup.py bdist_wheel for pycparser: started
2018-07-12 16:42:23.517134 |   Running setup.py bdist_wheel for pycparser: finished with status 'done'
2018-07-12 16:42:23.517522 |   Stored in directory: /home/jenkins/.cache/pip/wheels/c0/a1/27/5ba234bd77ea5a290cbf6d675259ec52293193467a12ef1f46
2018-07-12 16:42:23.532061 | Successfully built ansible PyYAML pycrypto XStatic-DataTables XStatic-Patternfly junit-xml XStatic Flask-Script XStatic-jQuery XStatic-Patternfly-Bootstrap-Treeview pyperclip subprocess32 MarkupSafe SQLAlchemy alembic itsdangerous PrettyTable unicodecsv wrapt Mako python-editor pycparser
2018-07-12 16:42:23.706125 | Installing collected packages: MarkupSafe, jinja2, PyYAML, pyasn1, six, pycparser, cffi, bcrypt, enum34, asn1crypto, idna, ipaddress, cryptography, pynacl, paramiko, pycrypto, ansible, devstack-tools, XStatic-DataTables, linecache2, traceback2, unittest2, extras, fixtures, python-mimeparse, testtools, python-subunit, XStatic-Patternfly, pytz, pyparsing, funcsigs, wrapt, debtcollector, iso8601, Babel, oslo.i18n, netifaces, netaddr, monotonic, oslo.utils, decorator, pygments, junit-xml, Werkzeug, click, itsdangerous, Flask, SQLAlchemy, Flask-SQLAlchemy, pyfakefs, Mako, python-editor, python-dateutil, alembic, Flask-Migrate, Frozen-Flask, XStatic, Flask-Script, XStatic-jQuery, pyperclip, contextlib2, wcwidth, subprocess32, cmd2, stevedore, PrettyTable, unicodecsv, cliff, XStatic-Patternfly-Bootstrap-Treeview, XStatic-Bootstrap-SCSS, msgpack, oslo.serialization, ara
2018-07-12 16:42:31.023743 | Successfully installed Babel-2.6.0 Flask-0.12.4 Flask-Migrate-2.2.1 Flask-SQLAlchemy-2.3.2 Flask-Script-2.0.6 Frozen-Flask-0.15 Mako-1.0.7 MarkupSafe-1.0 PrettyTable-0.7.2 PyYAML-3.13 SQLAlchemy-1.2.9 Werkzeug-0.14.1 XStatic-1.0.1 XStatic-Bootstrap-SCSS-3.3.7.1 XStatic-DataTables-1.10.15.1 XStatic-Patternfly-3.21.0.1 XStatic-Patternfly-Bootstrap-Treeview-2.1.3.2 XStatic-jQuery-1.10.2.1 alembic-0.9.10 ansible-2.3.2.0 ara-0.15.0 asn1crypto-0.24.0 bcrypt-3.1.4 cffi-1.11.5 click-6.7 cliff-2.13.0 cmd2-0.8.8 contextlib2-0.5.5 cryptography-2.2.2 debtcollector-1.19.0 decorator-4.3.0 devstack-tools-0.4.0 enum34-1.1.6 extras-1.0.0 fixtures-3.0.0 funcsigs-1.0.2 idna-2.7 ipaddress-1.0.22 iso8601-0.1.12 itsdangerous-0.24 jinja2-2.10 junit-xml-1.8 linecache2-1.0.0 monotonic-1.5 msgpack-0.5.6 netaddr-0.7.19 netifaces-0.10.7 oslo.i18n-3.20.0 oslo.serialization-2.27.0 oslo.utils-3.36.3 paramiko-2.4.1 pyasn1-0.4.3 pycparser-2.18 pycrypto-2.6.1 pyfakefs-3.4.3 pygments-2.2.0 pynacl-1.2.1 pyparsing-2.2.0 pyperclip-1.6.2 python-dateutil-2.7.3 python-editor-1.0.3 python-mimeparse-1.6.0 python-subunit-1.3.0 pytz-2018.5 six-1.11.0 stevedore-1.28.0 subprocess32-3.5.2 testtools-2.3.0 traceback2-1.4.0 unicodecsv-0.14.1 unittest2-1.1.0 wcwidth-0.1.7 wrapt-1.10.11
2018-07-12 16:42:31.684611 |  [WARNING]: No hosts matched, nothing to do
2018-07-12 16:42:34.932427 |  [WARNING]: No hosts matched, nothing to do
2018-07-12 16:42:36.638056 | localhost | SUCCESS => {
2018-07-12 16:42:36.638184 |     "changed": false, 
2018-07-12 16:42:36.638225 |     "path": "/home/jenkins/workspace/cinder-eseries-FCP/logs", 
2018-07-12 16:42:36.638242 |     "state": "absent"
2018-07-12 16:42:36.638250 | }
2018-07-12 16:42:37.548287 | localhost | SUCCESS => {
2018-07-12 16:42:37.548339 |     "changed": true, 
2018-07-12 16:42:37.548356 |     "gid": 1001, 
2018-07-12 16:42:37.548373 |     "group": "jenkins", 
2018-07-12 16:42:37.548388 |     "mode": "0775", 
2018-07-12 16:42:37.548404 |     "owner": "jenkins", 
2018-07-12 16:42:37.548437 |     "path": "/home/jenkins/workspace/cinder-eseries-FCP/logs", 
2018-07-12 16:42:37.548470 |     "size": 4096, 
2018-07-12 16:42:37.548501 |     "state": "directory", 
2018-07-12 16:42:37.548515 |     "uid": 1001
2018-07-12 16:42:37.548523 | }
2018-07-12 16:42:37.621676 | Setting up the hosts
2018-07-12 16:42:37.621805 | ... this takes a few seconds (logs at logs/devstack-gate-setup-host.txt.gz)
2018-07-12 16:43:14.825098 | Setting up the workspace
2018-07-12 16:43:14.825260 | ... this takes 3 - 5 minutes (logs at logs/devstack-gate-setup-workspace-new.txt.gz)
2018-07-12 16:46:38.187186 | localhost | SUCCESS | rc=0 >>
2018-07-12 16:46:38.187339 | 
2018-07-12 16:46:38.234462 | Job timeout set to: 221 minutes
2018-07-12 16:46:38.241775 | Running pre_test_hook
2018-07-12 16:46:38.243883 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L82:   tsfilter pre_test_hook
2018-07-12 16:46:38.244023 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L82:   tee /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate-pre_test_hook.txt
2018-07-12 16:46:38.244425 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:tsfilter:L93:   pre_test_hook
2018-07-12 16:46:38.244544 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:tsfilter:L101:   awk '
2018-07-12 16:46:38.244561 |     {
2018-07-12 16:46:38.244591 |         cmd ="date +\"%Y-%m-%d %H:%M:%S.%3N | \""
2018-07-12 16:46:38.244610 |         cmd | getline now
2018-07-12 16:46:38.244641 |         close("date +\"%Y-%m-%d %H:%M:%S.%3N | \"")
2018-07-12 16:46:38.244659 |         sub(/^/, now)
2018-07-12 16:46:38.244673 |         print
2018-07-12 16:46:38.244700 |         fflush()
2018-07-12 16:46:38.244710 |     }'
2018-07-12 16:46:38.247759 | 2018-07-12 16:46:38.247 | + :pre_test_hook:L0:   [[ master =~ ^stable/(mitaka|newton)$ ]]
2018-07-12 16:46:38.249042 | 2018-07-12 16:46:38.248 | + :pre_test_hook:L3:   [[ -e /home/jenkins/local.conf ]]
2018-07-12 16:46:38.250223 | 2018-07-12 16:46:38.249 | + :pre_test_hook:L4:   cp /home/jenkins/local.conf /opt/stack/new/devstack/local.conf
2018-07-12 16:46:38.250368 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:tsfilter:L103:   return 0
2018-07-12 16:46:38.250801 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L83:   local ret_val=0
2018-07-12 16:46:38.250922 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L84:   sudo mv /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate-pre_test_hook.txt /opt/stack/logs/
2018-07-12 16:46:38.256815 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L85:   set +o pipefail
2018-07-12 16:46:38.256904 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L86:   set +o xtrace
2018-07-12 16:46:38.257244 | Running gate_hook
2018-07-12 16:46:38.258420 | Job timeout set to: 221 minutes
2018-07-12 16:46:38.266211 | +++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L26:   dirname /opt/stack/new/devstack-gate/devstack-vm-gate.sh
2018-07-12 16:46:38.267229 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L26:   cd /opt/stack/new/devstack-gate
2018-07-12 16:46:38.267275 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L26:   pwd
2018-07-12 16:46:38.267525 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L26:   TOP_DIR=/opt/stack/new/devstack-gate
2018-07-12 16:46:38.267586 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L32:   source /opt/stack/new/devstack-gate/functions.sh
2018-07-12 16:46:38.267699 | ++ /opt/stack/new/devstack-gate/functions.sh:source:L19:   SUDO=sudo
2018-07-12 16:46:38.271542 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L37:   source /opt/stack/new/devstack/inc/ini-config
2018-07-12 16:46:38.272205 | +++ /opt/stack/new/devstack/inc/ini-config:source:L10:   set +o
2018-07-12 16:46:38.272295 | +++ /opt/stack/new/devstack/inc/ini-config:source:L10:   grep xtrace
2018-07-12 16:46:38.273582 | ++ /opt/stack/new/devstack/inc/ini-config:source:L10:   INC_CONF_TRACE='set -o xtrace'
2018-07-12 16:46:38.273629 | ++ /opt/stack/new/devstack/inc/ini-config:source:L11:   set +o xtrace
2018-07-12 16:46:38.275176 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L47:   echo 21445
2018-07-12 16:46:38.276021 | +++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L48:   readlink -f /opt/stack/new/devstack-gate/devstack-vm-gate.sh
2018-07-12 16:46:38.277277 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L48:   dirname /opt/stack/new/devstack-gate/devstack-vm-gate.sh
2018-07-12 16:46:38.277962 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L48:   source /opt/stack/new/devstack-gate/functions.sh
2018-07-12 16:46:38.278040 | ++ /opt/stack/new/devstack-gate/functions.sh:source:L19:   SUDO=sudo
2018-07-12 16:46:38.282122 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L51:   FIXED_RANGE=10.1.0.0/20
2018-07-12 16:46:38.282175 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L52:   IPV4_ADDRS_SAFE_TO_USE=10.1.0.0/20
2018-07-12 16:46:38.282222 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L53:   FLOATING_RANGE=172.24.5.0/24
2018-07-12 16:46:38.282269 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L54:   PUBLIC_NETWORK_GATEWAY=172.24.5.1
2018-07-12 16:46:38.282314 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L66:   FLOATING_HOST_PREFIX=172.24.4
2018-07-12 16:46:38.282355 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L67:   FLOATING_HOST_MASK=23
2018-07-12 16:46:38.282979 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L70:   ip link show
2018-07-12 16:46:38.283199 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L70:   sort -n
2018-07-12 16:46:38.283248 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L70:   head -1
2018-07-12 16:46:38.283796 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L70:   sed -ne 's/.*mtu \([0-9]\+\).*/\1/p'
2018-07-12 16:46:38.285153 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L70:   LOCAL_MTU=1400
2018-07-12 16:46:38.285206 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L73:   EXTERNAL_BRIDGE_MTU=1350
2018-07-12 16:46:38.288622 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L664:   [[ -n '' ]]
2018-07-12 16:46:38.288672 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L729:   cd /opt/stack/new/devstack
2018-07-12 16:46:38.288721 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L730:   setup_localrc new local.conf primary
2018-07-12 16:46:38.288873 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L265:   local localrc_oldnew=new
2018-07-12 16:46:38.288936 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L266:   local localrc_file=local.conf
2018-07-12 16:46:38.288986 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L267:   local role=primary
2018-07-12 16:46:38.289062 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L273:   local branch_for_matrix=master
2018-07-12 16:46:38.289119 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L277:   [[ -z true ]]
2018-07-12 16:46:38.289367 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L282:   [[ ! -z c-api,c-bak,c-sch,c-vol,cinder,dstat,g-api,g-reg,key,mysql,n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,rabbit,tempest,s-account,s-container,s-object,s-proxy,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client ]]
2018-07-12 16:46:38.289570 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L283:   MY_ENABLED_SERVICES=c-api,c-bak,c-sch,c-vol,cinder,dstat,g-api,g-reg,key,mysql,n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,rabbit,tempest,s-account,s-container,s-object,s-proxy,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client
2018-07-12 16:46:38.289619 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L328:   [[ ! -z '' ]]
2018-07-12 16:46:38.289665 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L332:   [[ '' == \1 ]]
2018-07-12 16:46:38.289740 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L338:   SKIP_EXERCISES=boot_from_volume,bundle,client-env,euca
2018-07-12 16:46:38.289783 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L340:   [[ 1 -eq 1 ]]
2018-07-12 16:46:38.289863 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L341:   localrc_set local.conf Q_USE_DEBUG_COMMAND True
2018-07-12 16:46:38.289909 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:38.289956 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=Q_USE_DEBUG_COMMAND
2018-07-12 16:46:38.289999 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:38.290061 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf Q_USE_DEBUG_COMMAND True
2018-07-12 16:46:38.450576 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L342:   localrc_set local.conf NETWORK_GATEWAY 10.1.0.1
2018-07-12 16:46:38.450666 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:38.450719 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=NETWORK_GATEWAY
2018-07-12 16:46:38.450768 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=10.1.0.1
2018-07-12 16:46:38.450868 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf NETWORK_GATEWAY 10.1.0.1
2018-07-12 16:46:38.604046 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L345:   [[ 0 -eq 1 ]]
2018-07-12 16:46:38.604169 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L355:   localrc_set local.conf USE_SCREEN False
2018-07-12 16:46:38.604236 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:38.604352 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=USE_SCREEN
2018-07-12 16:46:38.604401 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:38.604481 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf USE_SCREEN False
2018-07-12 16:46:38.757451 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L356:   localrc_set local.conf DEST /opt/stack/new
2018-07-12 16:46:38.757520 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:38.757578 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=DEST
2018-07-12 16:46:38.757629 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=/opt/stack/new
2018-07-12 16:46:38.757694 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf DEST /opt/stack/new
2018-07-12 16:46:38.897058 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L358:   localrc_set local.conf DATA_DIR /opt/stack/data
2018-07-12 16:46:38.897129 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:38.897189 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=DATA_DIR
2018-07-12 16:46:38.897242 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=/opt/stack/data
2018-07-12 16:46:38.897311 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf DATA_DIR /opt/stack/data
2018-07-12 16:46:39.041194 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L359:   localrc_set local.conf ACTIVE_TIMEOUT 90
2018-07-12 16:46:39.041287 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.041340 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=ACTIVE_TIMEOUT
2018-07-12 16:46:39.041385 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=90
2018-07-12 16:46:39.041473 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf ACTIVE_TIMEOUT 90
2018-07-12 16:46:39.210120 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L360:   localrc_set local.conf BOOT_TIMEOUT 90
2018-07-12 16:46:39.210217 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.210280 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=BOOT_TIMEOUT
2018-07-12 16:46:39.210335 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=90
2018-07-12 16:46:39.210413 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf BOOT_TIMEOUT 90
2018-07-12 16:46:39.353134 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L361:   localrc_set local.conf ASSOCIATE_TIMEOUT 60
2018-07-12 16:46:39.353236 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.353294 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=ASSOCIATE_TIMEOUT
2018-07-12 16:46:39.353341 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=60
2018-07-12 16:46:39.353424 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf ASSOCIATE_TIMEOUT 60
2018-07-12 16:46:39.488050 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L362:   localrc_set local.conf TERMINATE_TIMEOUT 60
2018-07-12 16:46:39.488136 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.488191 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=TERMINATE_TIMEOUT
2018-07-12 16:46:39.488238 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=60
2018-07-12 16:46:39.488340 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf TERMINATE_TIMEOUT 60
2018-07-12 16:46:39.624351 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L363:   localrc_set local.conf MYSQL_PASSWORD secretmysql
2018-07-12 16:46:39.624462 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.624521 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=MYSQL_PASSWORD
2018-07-12 16:46:39.624582 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=secretmysql
2018-07-12 16:46:39.624667 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf MYSQL_PASSWORD secretmysql
2018-07-12 16:46:39.765109 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L364:   localrc_set local.conf DATABASE_PASSWORD secretdatabase
2018-07-12 16:46:39.765194 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.765250 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=DATABASE_PASSWORD
2018-07-12 16:46:39.765314 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=secretdatabase
2018-07-12 16:46:39.765385 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf DATABASE_PASSWORD secretdatabase
2018-07-12 16:46:39.908739 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L365:   localrc_set local.conf RABBIT_PASSWORD secretrabbit
2018-07-12 16:46:39.908826 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:39.908881 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=RABBIT_PASSWORD
2018-07-12 16:46:39.908931 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=secretrabbit
2018-07-12 16:46:39.909003 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf RABBIT_PASSWORD secretrabbit
2018-07-12 16:46:40.061238 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L366:   localrc_set local.conf ADMIN_PASSWORD secretadmin
2018-07-12 16:46:40.061335 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.061391 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=ADMIN_PASSWORD
2018-07-12 16:46:40.061463 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=secretadmin
2018-07-12 16:46:40.061541 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf ADMIN_PASSWORD secretadmin
2018-07-12 16:46:40.204496 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L367:   localrc_set local.conf SERVICE_PASSWORD secretservice
2018-07-12 16:46:40.204599 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.204655 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SERVICE_PASSWORD
2018-07-12 16:46:40.204709 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=secretservice
2018-07-12 16:46:40.204794 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SERVICE_PASSWORD secretservice
2018-07-12 16:46:40.355319 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L368:   localrc_set local.conf SERVICE_TOKEN 111222333444
2018-07-12 16:46:40.355424 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.355511 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SERVICE_TOKEN
2018-07-12 16:46:40.355566 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=111222333444
2018-07-12 16:46:40.355654 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SERVICE_TOKEN 111222333444
2018-07-12 16:46:40.505955 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L369:   localrc_set local.conf SWIFT_HASH 1234123412341234
2018-07-12 16:46:40.506096 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.506150 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SWIFT_HASH
2018-07-12 16:46:40.506215 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=1234123412341234
2018-07-12 16:46:40.506301 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SWIFT_HASH 1234123412341234
2018-07-12 16:46:40.651577 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L370:   localrc_set local.conf ROOTSLEEP 0
2018-07-12 16:46:40.651662 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.651714 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=ROOTSLEEP
2018-07-12 16:46:40.651760 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=0
2018-07-12 16:46:40.651837 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf ROOTSLEEP 0
2018-07-12 16:46:40.796045 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L376:   localrc_set local.conf ERROR_ON_CLONE True
2018-07-12 16:46:40.796142 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.796200 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=ERROR_ON_CLONE
2018-07-12 16:46:40.796285 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:40.796360 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf ERROR_ON_CLONE True
2018-07-12 16:46:40.952002 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L383:   localrc_set local.conf INSTALL_TEMPEST False
2018-07-12 16:46:40.952105 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:40.952162 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=INSTALL_TEMPEST
2018-07-12 16:46:40.952222 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:40.952333 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf INSTALL_TEMPEST False
2018-07-12 16:46:41.099613 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L385:   localrc_set local.conf NOVNC_FROM_PACKAGE True
2018-07-12 16:46:41.099712 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:41.099794 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=NOVNC_FROM_PACKAGE
2018-07-12 16:46:41.099846 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:41.099927 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf NOVNC_FROM_PACKAGE True
2018-07-12 16:46:41.253217 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L386:   localrc_set local.conf ENABLED_SERVICES c-api,c-bak,c-sch,c-vol,cinder,dstat,g-api,g-reg,key,mysql,n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,rabbit,tempest,s-account,s-container,s-object,s-proxy,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client
2018-07-12 16:46:41.253308 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:41.253362 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=ENABLED_SERVICES
2018-07-12 16:46:41.253571 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=c-api,c-bak,c-sch,c-vol,cinder,dstat,g-api,g-reg,key,mysql,n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,rabbit,tempest,s-account,s-container,s-object,s-proxy,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client
2018-07-12 16:46:41.253774 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf ENABLED_SERVICES c-api,c-bak,c-sch,c-vol,cinder,dstat,g-api,g-reg,key,mysql,n-api,n-cond,n-cpu,n-crt,n-obj,n-sch,rabbit,tempest,s-account,s-container,s-object,s-proxy,q-agt,q-dhcp,q-fwaas,q-l3,q-lbaas,q-meta,q-metering,q-svc,quantum,placement-api,placement-client
2018-07-12 16:46:41.407429 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L387:   localrc_set local.conf SKIP_EXERCISES boot_from_volume,bundle,client-env,euca
2018-07-12 16:46:41.407616 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:41.407678 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SKIP_EXERCISES
2018-07-12 16:46:41.407747 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=boot_from_volume,bundle,client-env,euca
2018-07-12 16:46:41.407862 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SKIP_EXERCISES boot_from_volume,bundle,client-env,euca
2018-07-12 16:46:41.559054 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L389:   localrc_set local.conf SYSLOG False
2018-07-12 16:46:41.559139 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:41.559201 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SYSLOG
2018-07-12 16:46:41.559263 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:41.559330 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SYSLOG False
2018-07-12 16:46:41.715504 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L390:   localrc_set local.conf SCREEN_LOGDIR /opt/stack/new/screen-logs
2018-07-12 16:46:41.715609 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:41.715675 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SCREEN_LOGDIR
2018-07-12 16:46:41.715734 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=/opt/stack/new/screen-logs
2018-07-12 16:46:41.715812 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SCREEN_LOGDIR /opt/stack/new/screen-logs
2018-07-12 16:46:41.870111 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L391:   localrc_set local.conf LOGFILE /opt/stack/new/devstacklog.txt
2018-07-12 16:46:41.870212 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:41.870263 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=LOGFILE
2018-07-12 16:46:41.870337 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=/opt/stack/new/devstacklog.txt
2018-07-12 16:46:41.870433 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf LOGFILE /opt/stack/new/devstacklog.txt
2018-07-12 16:46:42.022121 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L392:   localrc_set local.conf VERBOSE True
2018-07-12 16:46:42.022236 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.022286 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=VERBOSE
2018-07-12 16:46:42.022333 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:42.022408 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf VERBOSE True
2018-07-12 16:46:42.169830 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L393:   localrc_set local.conf FIXED_RANGE 10.1.0.0/20
2018-07-12 16:46:42.169930 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.169983 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=FIXED_RANGE
2018-07-12 16:46:42.170033 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=10.1.0.0/20
2018-07-12 16:46:42.170126 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf FIXED_RANGE 10.1.0.0/20
2018-07-12 16:46:42.321791 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L394:   localrc_set local.conf IPV4_ADDRS_SAFE_TO_USE 10.1.0.0/20
2018-07-12 16:46:42.321894 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.321964 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=IPV4_ADDRS_SAFE_TO_USE
2018-07-12 16:46:42.322013 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=10.1.0.0/20
2018-07-12 16:46:42.322086 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf IPV4_ADDRS_SAFE_TO_USE 10.1.0.0/20
2018-07-12 16:46:42.469663 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L395:   localrc_set local.conf FLOATING_RANGE 172.24.5.0/24
2018-07-12 16:46:42.469772 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.469827 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=FLOATING_RANGE
2018-07-12 16:46:42.469892 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=172.24.5.0/24
2018-07-12 16:46:42.469981 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf FLOATING_RANGE 172.24.5.0/24
2018-07-12 16:46:42.617417 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L396:   localrc_set local.conf PUBLIC_NETWORK_GATEWAY 172.24.5.1
2018-07-12 16:46:42.617537 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.617596 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=PUBLIC_NETWORK_GATEWAY
2018-07-12 16:46:42.617659 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=172.24.5.1
2018-07-12 16:46:42.617751 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf PUBLIC_NETWORK_GATEWAY 172.24.5.1
2018-07-12 16:46:42.764653 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L397:   localrc_set local.conf FIXED_NETWORK_SIZE 4096
2018-07-12 16:46:42.764755 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.764813 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=FIXED_NETWORK_SIZE
2018-07-12 16:46:42.764863 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=4096
2018-07-12 16:46:42.764960 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf FIXED_NETWORK_SIZE 4096
2018-07-12 16:46:42.911729 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L398:   localrc_set local.conf VIRT_DRIVER libvirt
2018-07-12 16:46:42.911830 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:42.911881 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=VIRT_DRIVER
2018-07-12 16:46:42.911940 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=libvirt
2018-07-12 16:46:42.912008 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf VIRT_DRIVER libvirt
2018-07-12 16:46:43.047279 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L399:   localrc_set local.conf SWIFT_REPLICAS 1
2018-07-12 16:46:43.047374 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.047427 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SWIFT_REPLICAS
2018-07-12 16:46:43.047491 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=1
2018-07-12 16:46:43.047563 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SWIFT_REPLICAS 1
2018-07-12 16:46:43.225613 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L400:   localrc_set local.conf SWIFT_START_ALL_SERVICES False
2018-07-12 16:46:43.225713 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.225785 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=SWIFT_START_ALL_SERVICES
2018-07-12 16:46:43.225846 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:43.225922 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf SWIFT_START_ALL_SERVICES False
2018-07-12 16:46:43.371702 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L401:   localrc_set local.conf LOG_COLOR False
2018-07-12 16:46:43.371782 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.371838 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=LOG_COLOR
2018-07-12 16:46:43.371890 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:43.371978 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf LOG_COLOR False
2018-07-12 16:46:43.510650 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L403:   localrc_set local.conf UNDO_REQUIREMENTS False
2018-07-12 16:46:43.510736 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.510799 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=UNDO_REQUIREMENTS
2018-07-12 16:46:43.510848 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:43.510940 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf UNDO_REQUIREMENTS False
2018-07-12 16:46:43.646295 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L404:   localrc_set local.conf CINDER_PERIODIC_INTERVAL 10
2018-07-12 16:46:43.646379 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.646437 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=CINDER_PERIODIC_INTERVAL
2018-07-12 16:46:43.646519 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=10
2018-07-12 16:46:43.646592 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf CINDER_PERIODIC_INTERVAL 10
2018-07-12 16:46:43.782423 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L406:   localrc_set local.conf 'export OS_NO_CACHE' True
2018-07-12 16:46:43.782538 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.782612 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local 'key=export OS_NO_CACHE'
2018-07-12 16:46:43.782664 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:43.782741 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf 'export OS_NO_CACHE' True
2018-07-12 16:46:43.930610 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L407:   localrc_set local.conf LIBS_FROM_GIT ''
2018-07-12 16:46:43.930702 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:43.930767 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=LIBS_FROM_GIT
2018-07-12 16:46:43.930814 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=
2018-07-12 16:46:43.930881 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf LIBS_FROM_GIT ''
2018-07-12 16:46:44.078014 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L411:   localrc_set local.conf EBTABLES_RACE_FIX True
2018-07-12 16:46:44.078122 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.078188 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=EBTABLES_RACE_FIX
2018-07-12 16:46:44.078237 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:44.078306 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf EBTABLES_RACE_FIX True
2018-07-12 16:46:44.229990 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L414:   localrc_set local.conf DEBUG_LIBVIRT_COREDUMPS True
2018-07-12 16:46:44.230088 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.230148 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=DEBUG_LIBVIRT_COREDUMPS
2018-07-12 16:46:44.230196 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=True
2018-07-12 16:46:44.230279 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf DEBUG_LIBVIRT_COREDUMPS True
2018-07-12 16:46:44.377232 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L416:   [[ aio == \m\u\l\t\i\n\o\d\e ]]
2018-07-12 16:46:44.377349 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L421:   localrc_set local.conf CINDER_VOLUME_CLEAR none
2018-07-12 16:46:44.377406 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.377487 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=CINDER_VOLUME_CLEAR
2018-07-12 16:46:44.377542 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=none
2018-07-12 16:46:44.377628 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf CINDER_VOLUME_CLEAR none
2018-07-12 16:46:44.521066 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L423:   [[ 0 -eq 1 ]]
2018-07-12 16:46:44.521173 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L429:   [[ libvirt == \l\i\b\v\i\r\t ]]
2018-07-12 16:46:44.521222 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L430:   [[ -n qemu ]]
2018-07-12 16:46:44.521280 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L431:   localrc_set local.conf LIBVIRT_TYPE qemu
2018-07-12 16:46:44.521329 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.521377 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=LIBVIRT_TYPE
2018-07-12 16:46:44.521423 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=qemu
2018-07-12 16:46:44.521523 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf LIBVIRT_TYPE qemu
2018-07-12 16:46:44.660385 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L435:   [[ libvirt == \i\r\o\n\i\c ]]
2018-07-12 16:46:44.660475 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L464:   [[ libvirt == \x\e\n\a\p\i ]]
2018-07-12 16:46:44.660544 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L507:   [[ 1 -eq 1 ]]
2018-07-12 16:46:44.660609 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L514:   localrc_set local.conf VOLUME_BACKING_FILE_SIZE 24G
2018-07-12 16:46:44.660658 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.660712 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=VOLUME_BACKING_FILE_SIZE
2018-07-12 16:46:44.660768 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=24G
2018-07-12 16:46:44.660833 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf VOLUME_BACKING_FILE_SIZE 24G
2018-07-12 16:46:44.796020 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L518:   localrc_set local.conf TEMPEST_HTTP_IMAGE http://git.openstack.org/static/openstack.png
2018-07-12 16:46:44.796160 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.796284 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=TEMPEST_HTTP_IMAGE
2018-07-12 16:46:44.796359 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=http://git.openstack.org/static/openstack.png
2018-07-12 16:46:44.796462 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf TEMPEST_HTTP_IMAGE http://git.openstack.org/static/openstack.png
2018-07-12 16:46:44.946564 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L521:   [[ 0 -eq 1 ]]
2018-07-12 16:46:44.946641 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L525:   [[ -n '' ]]
2018-07-12 16:46:44.946689 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L534:   [[ 0 -eq 1 ]]
2018-07-12 16:46:44.946748 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L538:   [[ 0 -gt 1 ]]
2018-07-12 16:46:44.946795 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L547:   [[ 0 -eq 1 ]]
2018-07-12 16:46:44.946884 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L550:   localrc_set local.conf FORCE_CONFIG_DRIVE False
2018-07-12 16:46:44.946938 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L41:   local lcfile=local.conf
2018-07-12 16:46:44.946994 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L42:   local key=FORCE_CONFIG_DRIVE
2018-07-12 16:46:44.947067 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L43:   local value=False
2018-07-12 16:46:44.947160 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:localrc_set:L44:   /tmp/ansible/bin/dsconf setlc local.conf FORCE_CONFIG_DRIVE False
2018-07-12 16:46:45.088351 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L553:   [[ -n '' ]]
2018-07-12 16:46:45.088452 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L559:   [[ 0 -eq 1 ]]
2018-07-12 16:46:45.088523 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L564:   [[ aio != \a\i\o ]]
2018-07-12 16:46:45.088609 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L611:   [[ -e /tmp/dg-local.conf ]]
2018-07-12 16:46:45.088669 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L622:   [[ primary = sub ]]
2018-07-12 16:46:45.088713 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L633:   [[ -n '' ]]
2018-07-12 16:46:45.088768 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_localrc:L643:   [[ -n '' ]]
2018-07-12 16:46:45.088814 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L731:   [[ aio == \m\u\l\t\i\n\o\d\e ]]
2018-07-12 16:46:45.088854 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L738:   setup_networking
2018-07-12 16:46:45.088900 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_networking:L232:   local mode=devstack
2018-07-12 16:46:45.088961 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_networking:L235:   [[ aio != \m\u\l\t\i\n\o\d\e ]]
2018-07-12 16:46:45.089006 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_networking:L236:   [[ 1 -ne 1 ]]
2018-07-12 16:46:45.089057 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_networking:L243:   [[ aio == \m\u\l\t\i\n\o\d\e ]]
2018-07-12 16:46:45.089101 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L740:   setup_access_for_stack_user
2018-07-12 16:46:45.089208 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_access_for_stack_user:L657:   /tmp/ansible/bin/ansible all --sudo -f 5 -i /home/jenkins/workspace/cinder-eseries-FCP/inventory -m shell -a 'chown -R stack:stack '\''/opt/stack'\'''
2018-07-12 16:46:46.144409 |  [WARNING]: Consider using file module with owner rather than running chown
2018-07-12 16:46:46.144473 | localhost | SUCCESS | rc=0 >>
2018-07-12 16:46:46.144487 | 
2018-07-12 16:46:46.199679 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:setup_access_for_stack_user:L660:   /tmp/ansible/bin/ansible all --sudo -f 5 -i /home/jenkins/workspace/cinder-eseries-FCP/inventory -m shell -a 'chmod 777 '\''/home/jenkins/workspace/cinder-eseries-FCP/logs'\'''
2018-07-12 16:46:47.024852 |  [WARNING]: Consider using file module with mode rather than running chmod
2018-07-12 16:46:47.024909 | localhost | SUCCESS | rc=0 >>
2018-07-12 16:46:47.024919 | 
2018-07-12 16:46:47.077186 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L742:   echo 'Running devstack'
2018-07-12 16:46:47.077218 | Running devstack
2018-07-12 16:46:47.077285 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L743:   echo '... this takes 10 - 15 minutes (logs in logs/devstacklog.txt.gz)'
2018-07-12 16:46:47.077320 | ... this takes 10 - 15 minutes (logs in logs/devstacklog.txt.gz)
2018-07-12 16:46:47.077700 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L744:   date +%s
2018-07-12 16:46:47.078477 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L744:   start=1531414007
2018-07-12 16:46:47.078651 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L751:   /tmp/ansible/bin/ansible primary -f 5 -i /home/jenkins/workspace/cinder-eseries-FCP/inventory -m shell -a 'cd '\''/opt/stack/new/devstack'\'' && sudo -H -u stack DSTOOLS_VERSION=0.4.0 stdbuf -oL -eL ./stack.sh 2>&1 executable=/bin/bash'
2018-07-12 17:23:13.259593 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L754:   '[' -d /opt/stack/data/CA ']'
2018-07-12 17:23:13.259915 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L771:   /tmp/ansible/bin/ansible subnodes -f 5 -i /home/jenkins/workspace/cinder-eseries-FCP/inventory -m shell -a 'cd '\''/opt/stack/new/devstack'\'' && sudo -H -u stack DSTOOLS_VERSION=0.4.0 stdbuf -oL -eL ./stack.sh 2>&1 executable=/bin/bash'
2018-07-12 17:23:16.473148 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L774:   date +%s
2018-07-12 17:23:16.473978 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L774:   end=1531416196
2018-07-12 17:23:16.474065 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L775:   took=36
2018-07-12 17:23:16.474117 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L776:   [[ 36 -gt 20 ]]
2018-07-12 17:23:16.474238 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L777:   echo 'WARNING: devstack run took > 20 minutes, this is a very slow node.'
2018-07-12 17:23:16.474327 | WARNING: devstack run took > 20 minutes, this is a very slow node.
2018-07-12 17:23:16.474376 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L781:   discover_hosts
2018-07-12 17:23:16.474640 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:discover_hosts:L259:   /tmp/ansible/bin/ansible primary -f 5 -i /home/jenkins/workspace/cinder-eseries-FCP/inventory -m shell -a 'cd /opt/stack/new/devstack/ && (test -f tools/discover_hosts.sh && sudo -H -u stack DSTOOLS_VERSION=0.4.0 stdbuf -oL -eL ./tools/discover_hosts.sh) || (! test -f tools/discover_hosts.sh)'
2018-07-12 17:23:20.906987 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L785:   [[ -f /usr/bin/yum ]]
2018-07-12 17:23:20.907091 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L789:   POSTGRES_LOG_PATH='-d /var/log/postgresql'
2018-07-12 17:23:20.907159 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L790:   MYSQL_LOG_PATH='-d /var/log/mysql'
2018-07-12 17:23:20.907207 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L792:   [[ 0 -eq 1 ]]
2018-07-12 17:23:20.907257 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L798:   [[ ! -n -d /var/log/mysql ]]
2018-07-12 17:23:20.907313 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L805:   [[ 0 -eq 1 ]]
2018-07-12 17:23:20.907367 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L810:   [[ 1 -eq 1 ]]
2018-07-12 17:23:20.907458 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L811:   echo 'Removing sudo privileges for devstack user'
2018-07-12 17:23:20.907500 | Removing sudo privileges for devstack user
2018-07-12 17:23:20.907611 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L812:   /tmp/ansible/bin/ansible all --sudo -f 5 -i /home/jenkins/workspace/cinder-eseries-FCP/inventory -m file -a 'path=/etc/sudoers.d/50_stack_sh state=absent'
2018-07-12 17:23:21.932396 | localhost | SUCCESS => {
2018-07-12 17:23:21.932471 |     "changed": true, 
2018-07-12 17:23:21.932506 |     "path": "/etc/sudoers.d/50_stack_sh", 
2018-07-12 17:23:21.932523 |     "state": "absent"
2018-07-12 17:23:21.932531 | }
2018-07-12 17:23:21.995510 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L816:   [[ 0 -eq 1 ]]
2018-07-12 17:23:21.995935 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L822:   [[ 1 -eq 1 ]]
2018-07-12 17:23:21.996012 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L824:   [[ -d /opt/stack/new/tempest ]]
2018-07-12 17:23:21.996084 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L825:   sudo chown -R tempest:stack /opt/stack/new/tempest
2018-07-12 17:23:22.080980 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L829:   [[ -d /opt/stack/data/tempest ]]
2018-07-12 17:23:22.081083 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L830:   sudo chown -R tempest:stack /opt/stack/data/tempest
2018-07-12 17:23:22.087267 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L833:   [[ -d /opt/stack/new/devstack/files ]]
2018-07-12 17:23:22.087371 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L834:   sudo chmod -R o+rx /opt/stack/new/devstack/files
2018-07-12 17:23:22.093433 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L843:   [[ aio == \m\u\l\t\i\n\o\d\e ]]
2018-07-12 17:23:22.093493 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L848:   [[ 0 -eq 1 ]]
2018-07-12 17:23:22.093812 | ++ /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L856:   iniget /opt/stack/new/tempest/etc/tempest.conf neutron-feature-enabled api_extensions
2018-07-12 17:23:22.094242 | +++ /opt/stack/new/devstack-gate/functions.sh:iniget:L1026:   source /opt/stack/new/devstack/inc/ini-config
2018-07-12 17:23:22.120278 | +++++ /opt/stack/new/devstack/inc/ini-config:source:L10:   set +o
2018-07-12 17:23:22.120352 | +++++ /opt/stack/new/devstack/inc/ini-config:source:L10:   grep xtrace
2018-07-12 17:23:22.122598 | ++++ /opt/stack/new/devstack/inc/ini-config:source:L10:   INC_CONF_TRACE='set -o xtrace'
2018-07-12 17:23:22.122726 | ++++ /opt/stack/new/devstack/inc/ini-config:source:L11:   set +o xtrace
2018-07-12 17:23:22.124945 | +++ /opt/stack/new/devstack-gate/functions.sh:iniget:L1026:   iniget /opt/stack/new/tempest/etc/tempest.conf neutron-feature-enabled api_extensions
2018-07-12 17:23:22.125032 | +++ /opt/stack/new/devstack/inc/ini-config:iniget:L61:   local xtrace
2018-07-12 17:23:22.125825 | ++++ /opt/stack/new/devstack/inc/ini-config:iniget:L62:   set +o
2018-07-12 17:23:22.125946 | ++++ /opt/stack/new/devstack/inc/ini-config:iniget:L62:   grep xtrace
2018-07-12 17:23:22.127335 | +++ /opt/stack/new/devstack/inc/ini-config:iniget:L62:   xtrace='set -o xtrace'
2018-07-12 17:23:22.127475 | +++ /opt/stack/new/devstack/inc/ini-config:iniget:L63:   set +o xtrace
2018-07-12 17:23:22.130049 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L856:   neutron_extensions=
2018-07-12 17:23:22.130118 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L857:   [[ '' == \m\a\s\t\e\r ]]
2018-07-12 17:23:22.130182 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L864:   set -o errexit
2018-07-12 17:23:22.130225 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L866:   [[ '' != '' ]]
2018-07-12 17:23:22.130281 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L869:   TEMPEST_COMMAND='sudo -H -u tempest tox'
2018-07-12 17:23:22.130351 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L871:   cd /opt/stack/new/tempest
2018-07-12 17:23:22.130628 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L872:   [[ tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume|test_groups)) != '' ]]
2018-07-12 17:23:22.130675 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L873:   [[ 0 -eq 1 ]]
2018-07-12 17:23:22.130736 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L878:   echo 'Running tempest with a custom regex filter'
2018-07-12 17:23:22.130762 | Running tempest with a custom regex filter
2018-07-12 17:23:22.130897 | + /opt/stack/new/devstack-gate/devstack-vm-gate.sh:main:L879:   sudo -H -u tempest tox -eall -- 'tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume|test_groups))' --concurrency=1
2018-07-12 17:23:23.101051 | all develop-inst-noop: /opt/stack/new/tempest
2018-07-12 17:23:23.589924 | all installed: asn1crypto==0.24.0,Babel==2.6.0,bcrypt==3.1.4,cffi==1.11.5,cliff==2.13.0,cmd2==0.8.8,contextlib2==0.5.5,cryptography==2.2.2,debtcollector==1.19.0,enum34==1.1.6,extras==1.0.0,fasteners==0.14.1,fixtures==3.0.0,funcsigs==1.0.2,functools32==3.2.3.post2,future==0.16.0,idna==2.7,ipaddress==1.0.22,iso8601==0.1.12,jsonschema==2.6.0,linecache2==1.0.0,monotonic==1.5,msgpack==0.5.6,netaddr==0.7.19,netifaces==0.10.7,oslo.concurrency==3.27.0,oslo.config==6.3.0,oslo.context==2.21.0,oslo.i18n==3.20.0,oslo.log==3.39.0,oslo.serialization==2.27.0,oslo.utils==3.36.3,paramiko==2.4.1,pbr==4.1.0,prettytable==0.7.2,pyasn1==0.4.3,pycparser==2.18,pyinotify==0.9.6,PyNaCl==1.2.1,pyparsing==2.2.0,pyperclip==1.6.2,python-dateutil==2.7.3,python-mimeparse==1.6.0,python-subunit==1.3.0,pytz==2018.5,PyYAML==3.13,rfc3986==1.1.0,six==1.11.0,stestr==2.1.0,stevedore==1.28.0,subprocess32==3.5.2,-e git+https://git.openstack.org/openstack/tempest@e2a05dbc1cd64b442d18058ea0e64545ef5c6802#egg=tempest,testtools==2.3.0,traceback2==1.4.0,unicodecsv==0.14.1,unittest2==1.1.0,urllib3==1.23,voluptuous==0.11.1,wcwidth==0.1.7,wrapt==1.10.11
2018-07-12 17:23:23.589991 | all runtests: PYTHONHASHSEED='677729301'
2018-07-12 17:23:23.590032 | all runtests: commands[0] | find . -type f -name *.pyc -delete
2018-07-12 17:23:24.573936 | all runtests: commands[1] | tempest run --regex tempest.api.volume(?!.*(_upload|_shelved|consistency|s_cryptsetup|s_luks|force_detach_volume|test_groups)) --concurrency=1
2018-07-12 17:23:41.176838 | {0} tempest.api.volume.admin.test_backends_capabilities.BackendsCapabilitiesAdminTestsJSON.test_compare_volume_stats_values [0.379946s] ... ok
2018-07-12 17:23:41.228191 | {0} tempest.api.volume.admin.test_backends_capabilities.BackendsCapabilitiesAdminTestsJSON.test_get_capabilities_backend [0.051414s] ... ok
2018-07-12 17:24:23.755404 | {0} tempest.api.volume.admin.test_group_snapshots.GroupSnapshotsTest.test_create_group_from_group_snapshot [37.466898s] ... ok
2018-07-12 17:24:59.266930 | {0} tempest.api.volume.admin.test_group_snapshots.GroupSnapshotsTest.test_delete_group_snapshots_following_updated_volumes [35.494564s] ... ok
2018-07-12 17:25:15.030241 | {0} tempest.api.volume.admin.test_group_snapshots.GroupSnapshotsTest.test_group_snapshot_create_show_list_delete [15.760697s] ... ok
2018-07-12 17:25:34.774938 | {0} tempest.api.volume.admin.test_group_snapshots.GroupSnapshotsV319Test.test_reset_group_snapshot_status [15.610905s] ... ok
2018-07-12 17:25:39.668087 | {0} tempest.api.volume.admin.test_group_type_specs.GroupTypeSpecsTest.test_group_type_specs_create_show_update_list_delete [0.734430s] ... ok
2018-07-12 17:25:42.849568 | {0} tempest.api.volume.admin.test_group_types.GroupTypesTest.test_group_type_create_list_update_show [0.355086s] ... ok
2018-07-12 17:25:48.666398 | {0} setUpClass (tempest.api.volume.admin.test_multi_backend.VolumeMultiBackendTest) ... SKIPPED: Cinder multi-backend feature disabled
2018-07-12 17:25:50.853516 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_associate_disassociate_qos [0.762984s] ... ok
2018-07-12 17:25:51.000893 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_create_delete_qos_with_back_end_consumer [0.147601s] ... ok
2018-07-12 17:25:51.162279 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_create_delete_qos_with_both_consumer [0.161221s] ... ok
2018-07-12 17:25:51.342442 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_create_delete_qos_with_front_end_consumer [0.179789s] ... ok
2018-07-12 17:25:51.361469 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_get_qos [0.019227s] ... ok
2018-07-12 17:25:51.387296 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_list_qos [0.025568s] ... ok
2018-07-12 17:25:51.563163 | {0} tempest.api.volume.admin.test_qos.QosSpecsTestJSON.test_set_unset_qos_key [0.175262s] ... ok
2018-07-12 17:25:53.750537 | {0} setUpClass (tempest.api.volume.admin.test_snapshot_manage.SnapshotManageAdminTest) ... SKIPPED: Manage snapshot tests are disabled
2018-07-12 17:26:02.772983 | {0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsTest.test_reset_snapshot_status [2.348021s] ... ok
2018-07-12 17:26:06.835514 | {0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsTest.test_snapshot_force_delete_when_snapshot_is_creating [4.062368s] ... ok
2018-07-12 17:26:10.420784 | {0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsTest.test_snapshot_force_delete_when_snapshot_is_deleting [3.584691s] ... ok
2018-07-12 17:26:13.142816 | {0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsTest.test_snapshot_force_delete_when_snapshot_is_error [2.720794s] ... ok
2018-07-12 17:26:15.873845 | {0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsTest.test_snapshot_force_delete_when_snapshot_is_error_deleting [2.731614s] ... ok
2018-07-12 17:26:16.183265 | {0} tempest.api.volume.admin.test_snapshots_actions.SnapshotsActionsTest.test_update_snapshot_status [0.309086s] ... ok
2018-07-12 17:26:26.300132 | {0} tempest.api.volume.admin.test_user_messages.UserMessagesTest.test_delete_message [2.210143s] ... ok
2018-07-12 17:26:28.208095 | {0} tempest.api.volume.admin.test_user_messages.UserMessagesTest.test_list_show_messages [1.907820s] ... ok
2018-07-12 17:26:31.237380 | {0} tempest.api.volume.admin.test_volume_hosts.VolumeHostsAdminTestsJSON.test_list_hosts [0.103607s] ... ok
2018-07-12 17:26:31.307613 | {0} tempest.api.volume.admin.test_volume_hosts.VolumeHostsAdminTestsJSON.test_show_host [0.070473s] ... ok
2018-07-12 17:26:32.530913 | {0} setUpClass (tempest.api.volume.admin.test_volume_manage.VolumeManageAdminTest) ... SKIPPED: Manage volume tests are disabled
2018-07-12 17:26:33.566612 | {0} tempest.api.volume.admin.test_volume_pools.VolumePoolsAdminTestsJSON.test_get_pools_with_details [0.109103s] ... ok
2018-07-12 17:26:33.601135 | {0} tempest.api.volume.admin.test_volume_pools.VolumePoolsAdminTestsJSON.test_get_pools_without_details [0.034400s] ... ok
2018-07-12 17:26:36.266477 | {0} tempest.api.volume.admin.test_volume_quota_classes.VolumeQuotaClassesTest.test_show_default_quota [0.121032s] ... ok
2018-07-12 17:26:37.321733 | {0} tempest.api.volume.admin.test_volume_quota_classes.VolumeQuotaClassesTest.test_update_default_quota [1.054836s] ... ok
2018-07-12 17:26:40.997115 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_delete_quota [0.504850s] ... ok
2018-07-12 17:26:41.030788 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_list_default_quotas [0.032864s] ... ok
2018-07-12 17:26:41.065138 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_list_quotas [0.034990s] ... ok
2018-07-12 17:26:44.055681 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_quota_usage [2.989078s] ... ok
2018-07-12 17:26:49.292560 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_quota_usage_after_volume_transfer [5.234275s] ... ok
2018-07-12 17:26:49.341205 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_show_quota_usage [0.051108s] ... ok
2018-07-12 17:26:54.310545 | {0} tempest.api.volume.admin.test_volume_quotas.BaseVolumeQuotasAdminTestJSON.test_update_all_quota_resources_for_tenant [4.968760s] ... ok
2018-07-12 17:27:01.203458 | {0} tempest.api.volume.admin.test_volume_quotas_negative.BaseVolumeQuotasNegativeTestJSON.test_quota_volume_gigabytes [0.450503s] ... ok
2018-07-12 17:27:01.325022 | {0} tempest.api.volume.admin.test_volume_quotas_negative.BaseVolumeQuotasNegativeTestJSON.test_quota_volumes [0.122586s] ... ok
2018-07-12 17:27:04.979373 | {0} setUpClass (tempest.api.volume.admin.test_volume_retype.VolumeRetypeWithMigrationTest) ... SKIPPED: Cinder multi-backend feature disabled.
2018-07-12 17:27:09.828868 | {0} tempest.api.volume.admin.test_volume_retype.VolumeRetypeWithoutMigrationTest.test_available_volume_retype [3.433917s] ... ok
2018-07-12 17:27:14.731038 | {0} tempest.api.volume.admin.test_volume_services.VolumesServicesTestJSON.test_get_service_by_host_name [0.065120s] ... ok
2018-07-12 17:27:14.754478 | {0} tempest.api.volume.admin.test_volume_services.VolumesServicesTestJSON.test_get_service_by_service_and_host_name [0.027673s] ... ok
2018-07-12 17:27:14.772423 | {0} tempest.api.volume.admin.test_volume_services.VolumesServicesTestJSON.test_get_service_by_service_binary_name [0.017772s] ... ok
2018-07-12 17:27:16.691593 | {0} tempest.api.volume.admin.test_volume_services.VolumesServicesTestJSON.test_get_service_by_volume_host_name [1.915951s] ... ok
2018-07-12 17:27:16.711516 | {0} tempest.api.volume.admin.test_volume_services.VolumesServicesTestJSON.test_list_services [0.022293s] ... ok
2018-07-12 17:27:21.142481 | {0} tempest.api.volume.admin.test_volume_services_negative.VolumeServicesNegativeTest.test_disable_log_reason_with_no_reason [0.019555s] ... ok
2018-07-12 17:27:21.166732 | {0} tempest.api.volume.admin.test_volume_services_negative.VolumeServicesNegativeTest.test_disable_service_with_invalid_binary [0.024244s] ... ok
2018-07-12 17:27:21.189467 | {0} tempest.api.volume.admin.test_volume_services_negative.VolumeServicesNegativeTest.test_enable_service_with_invalid_host [0.022205s] ... ok
2018-07-12 17:27:21.214808 | {0} tempest.api.volume.admin.test_volume_services_negative.VolumeServicesNegativeTest.test_freeze_host_with_invalid_host [0.025300s] ... ok
2018-07-12 17:27:21.254614 | {0} tempest.api.volume.admin.test_volume_services_negative.VolumeServicesNegativeTest.test_thaw_host_with_invalid_host [0.038300s] ... ok
2018-07-12 17:27:34.532119 | {0} tempest.api.volume.admin.test_volume_snapshot_quotas_negative.VolumeSnapshotQuotasNegativeTestJSON.test_quota_volume_gigabytes_snapshots [0.428404s] ... ok
2018-07-12 17:27:34.619665 | {0} tempest.api.volume.admin.test_volume_snapshot_quotas_negative.VolumeSnapshotQuotasNegativeTestJSON.test_quota_volume_snapshots [0.091001s] ... ok
2018-07-12 17:27:44.095789 | {0} tempest.api.volume.admin.test_volume_type_access.VolumeTypesAccessTest.test_volume_type_access_add [2.206562s] ... ok
2018-07-12 17:27:44.440836 | {0} tempest.api.volume.admin.test_volume_type_access.VolumeTypesAccessTest.test_volume_type_access_list [0.346080s] ... ok
2018-07-12 17:27:53.170632 | {0} tempest.api.volume.admin.test_volume_types.VolumeTypesTest.test_volume_crud_with_volume_type_and_extra_specs [3.679261s] ... ok
2018-07-12 17:27:53.287191 | {0} tempest.api.volume.admin.test_volume_types.VolumeTypesTest.test_volume_type_create_get_delete [0.121779s] ... ok
2018-07-12 17:27:53.708039 | {0} tempest.api.volume.admin.test_volume_types.VolumeTypesTest.test_volume_type_encryption_create_get_update_delete [0.419831s] ... ok
2018-07-12 17:27:53.763200 | {0} tempest.api.volume.admin.test_volume_types.VolumeTypesTest.test_volume_type_list [0.055914s] ... ok
2018-07-12 17:27:53.922453 | {0} tempest.api.volume.admin.test_volume_types.VolumeTypesTest.test_volume_type_update [0.158533s] ... ok
2018-07-12 17:28:04.480134 | {0} tempest.api.volume.admin.test_volume_types_extra_specs.VolumeTypesExtraSpecsTest.test_volume_type_extra_spec_create_get_delete [0.520815s] ... ok
2018-07-12 17:28:04.634692 | {0} tempest.api.volume.admin.test_volume_types_extra_specs.VolumeTypesExtraSpecsTest.test_volume_type_extra_specs_list [0.155354s] ... ok
2018-07-12 17:28:05.069081 | {0} tempest.api.volume.admin.test_volume_types_extra_specs.VolumeTypesExtraSpecsTest.test_volume_type_extra_specs_update [0.432492s] ... ok
2018-07-12 17:28:08.670192 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_create_invalid_body [0.015892s] ... ok
2018-07-12 17:28:08.682389 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_create_none_body [0.015502s] ... ok
2018-07-12 17:28:08.749135 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_create_nonexistent_type_id [0.066396s] ... ok
2018-07-12 17:28:08.769517 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_delete_nonexistent_volume_type_id [0.020637s] ... ok
2018-07-12 17:28:08.796186 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_get_nonexistent_extra_spec_name [0.025971s] ... ok
2018-07-12 17:28:08.815537 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_get_nonexistent_volume_type_id [0.019278s] ... ok
2018-07-12 17:28:08.839381 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_list_nonexistent_volume_type_id [0.023525s] ... ok
2018-07-12 17:28:08.849684 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_update_multiple_extra_spec [0.010153s] ... ok
2018-07-12 17:28:08.860514 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_update_no_body [0.010551s] ... ok
2018-07-12 17:28:08.917167 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_update_none_extra_spec_id [0.056324s] ... ok
2018-07-12 17:28:08.979707 | {0} tempest.api.volume.admin.test_volume_types_extra_specs_negative.ExtraSpecsNegativeTest.test_update_nonexistent_extra_spec_id [0.062174s] ... ok
2018-07-12 17:28:11.853277 | {0} tempest.api.volume.admin.test_volume_types_negative.VolumeTypesNegativeTest.test_create_volume_with_private_volume_type [0.254291s] ... ok
2018-07-12 17:28:11.864525 | {0} tempest.api.volume.admin.test_volume_types_negative.VolumeTypesNegativeTest.test_create_with_empty_name [0.011645s] ... ok
2018-07-12 17:28:11.889013 | {0} tempest.api.volume.admin.test_volume_types_negative.VolumeTypesNegativeTest.test_delete_nonexistent_type_id [0.024247s] ... ok
2018-07-12 17:28:11.908762 | {0} tempest.api.volume.admin.test_volume_types_negative.VolumeTypesNegativeTest.test_get_nonexistent_type_id [0.019470s] ... ok
2018-07-12 17:28:18.558012 | {0} tempest.api.volume.admin.test_volumes_actions.VolumesActionsTest.test_volume_force_delete_when_volume_is_attaching [3.533740s] ... ok
2018-07-12 17:28:21.581654 | {0} tempest.api.volume.admin.test_volumes_actions.VolumesActionsTest.test_volume_force_delete_when_volume_is_creating [3.023446s] ... ok
2018-07-12 17:28:24.665549 | {0} tempest.api.volume.admin.test_volumes_actions.VolumesActionsTest.test_volume_force_delete_when_volume_is_error [3.083523s] ... ok
2018-07-12 17:28:27.848028 | {0} tempest.api.volume.admin.test_volumes_actions.VolumesActionsTest.test_volume_force_delete_when_volume_is_maintenance [3.178344s] ... ok
2018-07-12 17:28:30.012148 | {0} tempest.api.volume.admin.test_volumes_actions.VolumesActionsTest.test_volume_reset_status [2.167715s] ... ok
2018-07-12 17:28:37.330605 | {0} setUpClass (tempest.api.volume.admin.test_volumes_backup.VolumesBackupsAdminTest) ... SKIPPED: Cinder backup feature disabled
2018-07-12 17:28:47.371203 | {0} tempest.api.volume.admin.test_volumes_list.VolumesListAdminTestJSON.test_volume_list_param_tenant [3.272511s] ... ok
2018-07-12 17:28:54.822878 | {0} tempest.api.volume.test_availability_zone.AvailabilityZoneTestJSON.test_get_availability_zone_list [0.104291s] ... ok
2018-07-12 17:28:56.399174 | {0} tempest.api.volume.test_extensions.ExtensionsTestJSON.test_list_extensions [0.106635s] ... ok
2018-07-12 17:29:29.815003 | {0} tempest.api.volume.test_image_metadata.VolumesImageMetadata.test_update_show_delete_image_metadata [0.708262s] ... ok
2018-07-12 17:29:38.434616 | {0} tempest.api.volume.test_snapshot_metadata.SnapshotMetadataTestJSON.test_crud_snapshot_metadata [0.585277s] ... ok
2018-07-12 17:29:39.090921 | {0} tempest.api.volume.test_snapshot_metadata.SnapshotMetadataTestJSON.test_update_show_snapshot_metadata_item [0.659297s] ... ok
2018-07-12 17:29:44.316087 | {0} tempest.api.volume.test_versions.VersionsTest.test_list_versions [0.009400s] ... ok
2018-07-12 17:29:48.183086 | {0} tempest.api.volume.test_volume_absolute_limits.AbsoluteLimitsTests.test_get_volume_absolute_limits [0.051729s] ... ok
2018-07-12 17:30:08.638538 | {0} tempest.api.volume.test_volume_delete_cascade.VolumesDeleteCascade.test_volume_delete_cascade [16.751166s] ... ok
2018-07-12 17:30:43.591853 | {0} tempest.api.volume.test_volume_delete_cascade.VolumesDeleteCascade.test_volume_from_snapshot_cascade_delete [34.942939s] ... ok
2018-07-12 17:30:49.442505 | {0} tempest.api.volume.test_volume_metadata.VolumesMetadataTest.test_crud_volume_metadata [0.706263s] ... ok
2018-07-12 17:30:50.199458 | {0} tempest.api.volume.test_volume_metadata.VolumesMetadataTest.test_update_show_volume_metadata_item [0.757423s] ... ok
2018-07-12 17:30:58.127440 | {0} tempest.api.volume.test_volume_transfers.VolumesTransfersTest.test_create_get_list_accept_volume_transfer [3.889610s] ... ok
2018-07-12 17:31:01.348850 | {0} tempest.api.volume.test_volume_transfers.VolumesTransfersTest.test_create_list_delete_volume_transfer [3.221338s] ... ok
2018-07-12 17:31:29.556934 | {0} tempest.api.volume.test_volumes_actions.VolumesActionsTest.test_attach_detach_volume_to_instance [17.158718s] ... ok
2018-07-12 17:31:38.455469 | {0} tempest.api.volume.test_volumes_actions.VolumesActionsTest.test_get_volume_attachment [8.894109s] ... ok
2018-07-12 17:31:39.320475 | {0} tempest.api.volume.test_volumes_actions.VolumesActionsTest.test_reserve_unreserve_volume [0.884632s] ... ok
2018-07-12 17:31:39.830577 | {0} tempest.api.volume.test_volumes_actions.VolumesActionsTest.test_volume_bootable [0.508368s] ... ok
2018-07-12 17:31:40.335844 | {0} tempest.api.volume.test_volumes_actions.VolumesActionsTest.test_volume_readonly_update [0.505930s] ... ok
2018-07-12 17:31:46.604864 | {0} setUpClass (tempest.api.volume.test_volumes_backup.VolumesBackupsTest) ... SKIPPED: Cinder backup feature disabled
2018-07-12 17:31:46.605980 | {0} setUpClass (tempest.api.volume.test_volumes_backup.VolumesBackupsV39Test) ... SKIPPED: Cinder backup feature disabled
2018-07-12 17:32:23.053180 | {0} tempest.api.volume.test_volumes_clone.VolumesCloneTest.test_create_from_bootable_volume [35.688513s] ... ok
2018-07-12 17:32:57.574512 | {0} tempest.api.volume.test_volumes_clone.VolumesCloneTest.test_create_from_volume [34.501104s] ... ok
2018-07-12 17:33:06.968624 | {0} tempest.api.volume.test_volumes_clone_negative.VolumesCloneNegativeTest.test_create_from_volume_decreasing_size [1.835347s] ... ok
2018-07-12 17:33:10.329446 | {0} tempest.api.volume.test_volumes_extend.VolumesExtendAttachedTest.test_extend_attached_volume ... SKIPPED: Attached volume extend is disabled.
2018-07-12 17:33:15.976412 | {0} tempest.api.volume.test_volumes_extend.VolumesExtendTest.test_volume_extend [3.315781s] ... ok
2018-07-12 17:33:25.004659 | {0} tempest.api.volume.test_volumes_extend.VolumesExtendTest.test_volume_extend_when_volume_has_snapshot [9.012405s] ... ok
2018-07-12 17:33:41.446134 | {0} tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_update_delete [8.474221s] ... ok
2018-07-12 17:34:12.060982 | {0} tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_update_delete_as_clone [30.610519s] ... ok
2018-07-12 17:34:34.078479 | {0} tempest.api.volume.test_volumes_get.VolumesGetTest.test_volume_create_get_update_delete_from_image [22.011562s] ... ok
2018-07-12 17:34:41.398407 | {0} tempest.api.volume.test_volumes_get.VolumesSummaryTest.test_show_volume_summary [0.265531s] ... ok
2018-07-12 17:34:49.449784 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list [0.059175s] ... ok
2018-07-12 17:34:49.500947 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_by_name [0.053288s] ... ok
2018-07-12 17:34:49.571827 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_details_by_name [0.070706s] ... ok
2018-07-12 17:34:49.989507 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_details_pagination [0.413349s] ... ok
2018-07-12 17:34:50.196351 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_details_with_multiple_params [0.209309s] ... ok
2018-07-12 17:34:50.503831 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_pagination [0.307001s] ... ok
2018-07-12 17:34:50.544562 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_param_display_name_and_status [0.041346s] ... ok
2018-07-12 17:34:50.631865 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_with_detail_param_display_name_and_status [0.081242s] ... ok
2018-07-12 17:34:50.729531 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_with_detail_param_marker [0.102997s] ... ok
2018-07-12 17:34:50.808490 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_with_detail_param_metadata [0.078554s] ... ok
2018-07-12 17:34:50.897959 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_with_details [0.089385s] ... ok
2018-07-12 17:34:50.943689 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volume_list_with_param_metadata [0.045817s] ... ok
2018-07-12 17:34:51.051574 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volumes_list_by_availability_zone [0.107019s] ... ok
2018-07-12 17:34:51.150332 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volumes_list_by_bootable [0.098309s] ... ok
2018-07-12 17:34:51.244370 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volumes_list_by_status [0.093820s] ... ok
2018-07-12 17:34:51.350023 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volumes_list_details_by_availability_zone [0.105409s] ... ok
2018-07-12 17:34:51.439114 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volumes_list_details_by_bootable [0.088527s] ... ok
2018-07-12 17:34:51.530497 | {0} tempest.api.volume.test_volumes_list.VolumesListTestJSON.test_volumes_list_details_by_status [0.091226s] ... ok
2018-07-12 17:35:05.072215 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_attach_volumes_with_nonexistent_volume_id [5.939359s] ... ok
2018-07-12 17:35:05.898019 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_from_deactivated_image [0.831053s] ... ok
2018-07-12 17:35:06.547359 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_from_image_with_decreasing_size [0.649136s] ... ok
2018-07-12 17:35:06.561409 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_with_invalid_size [0.014295s] ... ok
2018-07-12 17:35:06.602184 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_with_nonexistent_snapshot_id [0.040895s] ... ok
2018-07-12 17:35:06.652173 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_with_nonexistent_source_volid [0.049290s] ... ok
2018-07-12 17:35:06.673461 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_with_nonexistent_volume_type [0.020791s] ... ok
2018-07-12 17:35:06.688525 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_with_size_negative [0.015490s] ... ok
2018-07-12 17:35:06.703523 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_with_size_zero [0.014508s] ... ok
2018-07-12 17:35:06.750100 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_create_volume_without_passing_size [0.046545s] ... ok
2018-07-12 17:35:06.789226 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_delete_invalid_volume_id [0.038679s] ... ok
2018-07-12 17:35:06.796974 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_delete_volume_without_passing_volume_id [0.007672s] ... ok
2018-07-12 17:35:06.833906 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_detach_volumes_with_invalid_volume_id [0.036532s] ... ok
2018-07-12 17:35:06.881720 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_get_invalid_volume_id [0.047553s] ... ok
2018-07-12 17:35:06.890758 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_get_volume_without_passing_volume_id [0.008987s] ... ok
2018-07-12 17:35:06.962276 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_list_volumes_detail_with_invalid_status [0.070825s] ... ok
2018-07-12 17:35:07.217479 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_list_volumes_detail_with_nonexistent_name [0.254825s] ... ok
2018-07-12 17:35:07.273540 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_list_volumes_with_invalid_status [0.055636s] ... ok
2018-07-12 17:35:07.320311 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_list_volumes_with_nonexistent_name [0.046520s] ... ok
2018-07-12 17:35:07.597106 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_reserve_volume_with_negative_volume_status [0.275828s] ... ok
2018-07-12 17:35:07.641294 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_reserve_volume_with_nonexistent_volume_id [0.044243s] ... ok
2018-07-12 17:35:07.689807 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_unreserve_volume_with_nonexistent_volume_id [0.048248s] ... ok
2018-07-12 17:35:07.699269 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_update_volume_with_empty_volume_id [0.009321s] ... ok
2018-07-12 17:35:07.735713 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_update_volume_with_invalid_volume_id [0.036290s] ... ok
2018-07-12 17:35:07.780046 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_update_volume_with_nonexistent_volume_id [0.043889s] ... ok
2018-07-12 17:35:07.827021 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_delete_nonexistent_volume_id [0.046226s] ... ok
2018-07-12 17:35:07.885018 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_extend_with_None_size [0.013345s] ... ok
2018-07-12 17:35:07.885476 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_extend_with_non_number_size [0.011903s] ... ok
2018-07-12 17:35:07.902615 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_extend_with_nonexistent_volume_id [0.050237s] ... ok
2018-07-12 17:35:07.916996 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_extend_with_size_smaller_than_original_size [0.013990s] ... ok
2018-07-12 17:35:07.965209 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_extend_without_passing_volume_id [0.047550s] ... ok
2018-07-12 17:35:08.011567 | {0} tempest.api.volume.test_volumes_negative.VolumesNegativeTest.test_volume_get_nonexistent_volume_id [0.046481s] ... ok
2018-07-12 17:35:13.957965 | {0} tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_snapshot_backup ... SKIPPED: Cinder backup is disabled
2018-07-12 17:35:50.330448 | {0} tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_snapshot_create_delete_with_volume_in_use [36.362339s] ... ok
2018-07-12 17:35:58.080931 | {0} tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_snapshot_create_get_list_update_delete [7.750100s] ... ok
2018-07-12 17:36:29.261599 | {0} tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_snapshot_create_offline_delete_online [31.176068s] ... ok
2018-07-12 17:36:55.736541 | {0} tempest.api.volume.test_volumes_snapshots.VolumesSnapshotTestJSON.test_volume_from_snapshot [26.469379s] ... ok
2018-07-12 17:37:14.411720 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_limit [0.038409s] ... ok
2018-07-12 17:37:14.478101 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_limit_equals_infinite [0.066133s] ... ok
2018-07-12 17:37:14.504458 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_limit_equals_zero [0.026256s] ... ok
2018-07-12 17:37:14.569738 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_marker [0.065081s] ... ok
2018-07-12 17:37:14.597501 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_sort_created_at_asc [0.027627s] ... ok
2018-07-12 17:37:14.624423 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_sort_created_at_desc [0.026360s] ... ok
2018-07-12 17:37:14.662680 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_sort_id_asc [0.038161s] ... ok
2018-07-12 17:37:14.698145 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_sort_id_desc [0.035123s] ... ok
2018-07-12 17:37:14.737756 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_sort_name_asc [0.039241s] ... ok
2018-07-12 17:37:14.764189 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshot_list_param_sort_name_desc [0.026530s] ... ok
2018-07-12 17:37:14.855497 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshots_list_details_with_params [0.090398s] ... ok
2018-07-12 17:37:14.933986 | {0} tempest.api.volume.test_volumes_snapshots_list.VolumesSnapshotListTestJSON.test_snapshots_list_with_params [0.078296s] ... ok
2018-07-12 17:37:24.900785 | {0} tempest.api.volume.test_volumes_snapshots_negative.VolumesSnapshotNegativeTestJSON.test_create_snapshot_with_nonexistent_volume_id [0.129807s] ... ok
2018-07-12 17:37:24.950955 | {0} tempest.api.volume.test_volumes_snapshots_negative.VolumesSnapshotNegativeTestJSON.test_create_snapshot_without_passing_volume_id [0.050552s] ... ok
2018-07-12 17:37:24.963519 | {0} tempest.api.volume.test_volumes_snapshots_negative.VolumesSnapshotNegativeTestJSON.test_list_snapshot_invalid_param_limit [0.012470s] ... ok
2018-07-12 17:37:24.995379 | {0} tempest.api.volume.test_volumes_snapshots_negative.VolumesSnapshotNegativeTestJSON.test_list_snapshots_invalid_param_marker [0.031479s] ... ok
2018-07-12 17:37:25.012215 | {0} tempest.api.volume.test_volumes_snapshots_negative.VolumesSnapshotNegativeTestJSON.test_list_snapshots_invalid_param_sort [0.016749s] ... ok
2018-07-12 17:37:30.984394 | {0} tempest.api.volume.test_volumes_snapshots_negative.VolumesSnapshotNegativeTestJSON.test_volume_from_snapshot_decreasing_size [5.969833s] ... ok
2018-07-12 17:37:38.381094 | 
2018-07-12 17:37:38.381243 | ======
2018-07-12 17:37:38.381258 | Totals
2018-07-12 17:37:38.381281 | ======
2018-07-12 17:37:38.381303 | Ran: 190 tests in 849.0000 sec.
2018-07-12 17:37:38.381318 |  - Passed: 181
2018-07-12 17:37:38.381337 |  - Skipped: 9
2018-07-12 17:37:38.381363 |  - Expected Fail: 0
2018-07-12 17:37:38.381391 |  - Unexpected Success: 0
2018-07-12 17:37:38.381423 |  - Failed: 0
2018-07-12 17:37:38.381458 | Sum of execute time for each test: 531.9064 sec.
2018-07-12 17:37:38.381473 | 
2018-07-12 17:37:38.381487 | ==============
2018-07-12 17:37:38.381512 | Worker Balance
2018-07-12 17:37:38.381534 | ==============
2018-07-12 17:37:38.381576 |  - Worker 0 (190 tests) => 0:13:50.189240
2018-07-12 17:37:38.481704 | ___________________________________ summary ____________________________________
2018-07-12 17:37:38.481851 |   all: commands succeeded
2018-07-12 17:37:38.481882 |   congratulations :)
2018-07-12 17:37:38.533274 | Job timeout set to: 170 minutes
2018-07-12 17:37:38.556320 | Running post_test_hook
2018-07-12 17:37:38.558806 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L82:   tsfilter post_test_hook
2018-07-12 17:37:38.559022 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L82:   tee /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate-post_test_hook.txt
2018-07-12 17:37:38.559134 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:tsfilter:L93:   post_test_hook
2018-07-12 17:37:38.559941 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:tsfilter:L101:   awk '
2018-07-12 17:37:38.559983 |     {
2018-07-12 17:37:38.560029 |         cmd ="date +\"%Y-%m-%d %H:%M:%S.%3N | \""
2018-07-12 17:37:38.560048 |         cmd | getline now
2018-07-12 17:37:38.560080 |         close("date +\"%Y-%m-%d %H:%M:%S.%3N | \"")
2018-07-12 17:37:38.560097 |         sub(/^/, now)
2018-07-12 17:37:38.560111 |         print
2018-07-12 17:37:38.560126 |         fflush()
2018-07-12 17:37:38.560136 |     }'
2018-07-12 17:37:38.563427 | 2018-07-12 17:37:38.563 | + :post_test_hook:L0:   [[ -f /opt/stack/new/devstack.subunit ]]
2018-07-12 17:37:38.563516 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:tsfilter:L103:   return 0
2018-07-12 17:37:38.564098 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L83:   local ret_val=0
2018-07-12 17:37:38.564229 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L84:   sudo mv /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate-post_test_hook.txt /opt/stack/logs/
2018-07-12 17:37:38.603641 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L85:   set +o pipefail
2018-07-12 17:37:38.603729 | + /home/jenkins/workspace/cinder-eseries-FCP/devstack-gate/functions.sh:call_hook_if_defined:L86:   set +o xtrace
2018-07-12 17:37:38.603758 | Cleaning up host
2018-07-12 17:37:38.603804 | ... this takes 3 - 4 minutes (logs at logs/devstack-gate-cleanup-host.txt.gz)
2018-07-12 17:40:08.218795 |  [WARNING]: No hosts matched, nothing to do
2018-07-12 17:40:12.996126 | Done.
2018-07-12 17:40:14.594236 | SUCCESSFULLY FINISHED
2018-07-12 17:40:14.596268 | [Zuul] Task exit code: 0
2018-07-12 17:40:16.081955 | [Zuul] Job complete, result: SUCCESS