Project

General

Profile

Bug #12725 » centos7.log

Loïc Dachary, 08/18/2015 07:28 PM

 
2015-08-18T19:00:09.409 DEBUG:teuthology.run:Teuthology command: teuthology /tmp/teuthology-worker.fqtcUT.tmp -- --verbose --lock --description ceph-deploy/basic/{ceph-deploy-overrides/disable_diff_journal_disk.yaml config_options/cephdeploy_conf.yaml distros/centos_7.0.yaml tasks/ceph-deploy_hello_world.yaml} --name ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack --block --owner scheduled_ubuntu@teuthology --archive /usr/share/nginx/html/ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack/22
2015-08-18T19:00:09.459 DEBUG:teuthology.report:Pushing job info to http://localhost:8080/
2015-08-18T19:00:09.529 DEBUG:teuthology.run:Config:
archive-on-error: true
archive_path: /usr/share/nginx/html/ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack/22
archive_upload_key: teuthology/openstack/archive-key
branch: wip-11881-multipath
description: ceph-deploy/basic/{ceph-deploy-overrides/disable_diff_journal_disk.yaml
config_options/cephdeploy_conf.yaml distros/centos_7.0.yaml tasks/ceph-deploy_hello_world.yaml}
email: loic@dachary.org
job_id: '22'
last_in_suite: false
machine_type: openstack
name: ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack
nuke-on-error: true
openstack:
machine:
cpus: 1
disk: 10
ram: 2000
volumes:
count: 3
size: 10
os_type: centos
os_version: '7.0'
overrides:
admin_socket:
branch: wip-11881-multipath
ceph:
conf:
global:
mon lease: 15
mon lease ack timeout: 25
osd heartbeat grace: 100
mon:
debug mon: 20
debug ms: 1
debug paxos: 20
osd:
debug filestore: 20
debug journal: 20
debug ms: 1
debug osd: 20
log-whitelist:
- slow request
sha1: bc2c1c3b2f205e322639aef89956f7475e064ac2
ceph-deploy:
branch:
dev: wip-11881-multipath
conf:
client:
log file: /var/log/ceph/ceph-$name.$pid.log
global:
debug ms: 1
mon pg warn min per osd: 2
osd pool default size: 2
mon:
debug mon: 10
debug ms: 20
debug paxos: 20
osd default pool size: 2
osd:
debug osd: 10
separate_journal_disk: null
install:
ceph:
sha1: bc2c1c3b2f205e322639aef89956f7475e064ac2
rgw:
default_idle_timeout: 1200
s3tests:
idle_timeout: 1200
workunit:
sha1: bc2c1c3b2f205e322639aef89956f7475e064ac2
owner: scheduled_ubuntu@teuthology
priority: 1000
roles:
- - mon.a
- mds.0
- osd.0
- - osd.1
- mon.b
- client.0
sha1: bc2c1c3b2f205e322639aef89956f7475e064ac2
suite: ceph-deploy
suite_branch: wip-11881-multipath
suite_path: /home/ubuntu/src/ceph-qa-suite_wip-11881-multipath
tasks:
- ansible.cephlab: null
- clock.check: null
- install:
extras: true
- print: '**** done install extras'
- ssh_keys: null
- print: '**** done ssh_keys'
- ceph-deploy: null
- print: '**** done ceph-deploy'
- workunit:
clients:
client.0:
- ceph-deploy/ceph-deploy_hello_world.sh
- print: '**** done ceph-deploy/ceph-deploy_hello_world.sh'
teuthology_branch: master
tube: openstack
verbose: true
worker_log: /tmp/log/worker.openstack.3390
2015-08-18T19:00:09.529 INFO:teuthology.run:suite_path is set to /home/ubuntu/src/ceph-qa-suite_wip-11881-multipath; will attempt to use it
2015-08-18T19:00:09.529 INFO:teuthology.run:Found tasks at /home/ubuntu/src/ceph-qa-suite_wip-11881-multipath/tasks
2015-08-18T19:00:09.534 INFO:teuthology.run_tasks:Running task internal.check_packages...
2015-08-18T19:00:09.534 INFO:teuthology.task.internal:Checking packages...
2015-08-18T19:00:09.537 INFO:teuthology.task.internal:Checking packages for os_type,'centos' flavor 'basic' and ceph hash 'bc2c1c3b2f205e322639aef89956f7475e064ac2'
2015-08-18T19:00:09.537 INFO:teuthology.packaging:Looking for package version: http://gitbuilder.ceph.com/ceph-rpm-centos7-x86_64-basic/sha1/bc2c1c3b2f205e322639aef89956f7475e064ac2/version
2015-08-18T19:00:09.846 INFO:teuthology.packaging:Found version: 9.0.2
2015-08-18T19:00:09.846 INFO:teuthology.task.internal:Found packages for ceph version 9.0.2
2015-08-18T19:00:09.848 INFO:teuthology.run_tasks:Running task internal.lock_machines...
2015-08-18T19:00:09.848 INFO:teuthology.task.internal:Locking machines...
2015-08-18T19:00:09.848 DEBUG:teuthology.report:Pushing job info to http://localhost:8080/
2015-08-18T19:00:09.914 DEBUG:teuthology.provision:ProvisionOpenStack: {'machine': {'disk': 20, 'ram': 8000, 'cpus': 1}, 'subnet': '149.202.160.0/19', 'volumes': {'count': 0, 'size': 1}, 'user-data': 'teuthology/openstack/openstack-{os_type}-{os_version}-user-data.txt', 'ip': '149.202.169.83', 'flavor-select-regexp': '^(vps|eg)-', 'nameserver': '149.202.169.83'}
2015-08-18T19:00:09.914 DEBUG:teuthology.provision:ProvisionOpenStack:create
2015-08-18T19:00:09.914 DEBUG:teuthology.misc:openstack image list -f json --property name='teuthology-centos-7.0'
2015-08-18T19:00:11.554 DEBUG:teuthology.misc:openstack image list -f json --property name='teuthology-centos-7.0' output [{"ID": "94967743-087d-44d3-a9bc-1bfe9481127b", "Name": "teuthology-centos-7.0"}]

2015-08-18T19:00:11.554 DEBUG:teuthology.misc:openstack flavor list -f json
2015-08-18T19:00:12.643 DEBUG:teuthology.misc:openstack flavor list -f json output [{"ID": "0c36bb1d-bd1e-4294-ac75-60fd727054c8", "Name": "win-eg-15", "RAM": 15000, "Disk": 400, "Ephemeral": 0, "VCPUs": 4, "Is Public": true}, {"ID": "0e2b8841-d764-49b4-b2ac-24c8df2c6806", "Name": "sp-30", "RAM": 30000, "Disk": 200, "Ephemeral": 0, "VCPUs": 2, "Is Public": true}, {"ID": "169e7020-0436-4e8c-b2c8-213a57a044b5", "Name": "win-sp-120", "RAM": 120000, "Disk": 800, "Ephemeral": 0, "VCPUs": 8, "Is Public": true}, {"ID": "18811d09-053e-4ad0-b297-3c11ceefd136", "Name": "sp-60", "RAM": 60000, "Disk": 400, "Ephemeral": 0, "VCPUs": 4, "Is Public": true}, {"ID": "1e2c13fc-4ba9-4773-a13e-75ce96fb4e96", "Name": "eg-120", "RAM": 120000, "Disk": 1600, "Ephemeral": 0, "VCPUs": 32, "Is Public": true}, {"ID": "1e5a7cf5-d58c-4633-8069-5aba49b00be1", "Name": "win-sp-240", "RAM": 240000, "Disk": 1600, "Ephemeral": 0, "VCPUs": 16, "Is Public": true}, {"ID": "22096e9d-5150-4f54-bb8d-6c8b243a28bb", "Name": "win-sp-60", "RAM": 60000, "Disk": 400, "Ephemeral": 0, "VCPUs": 4, "Is Public": true}, {"ID": "23ec7924-483c-4414-9aaf-bf03575f0bfe", "Name": "eg-15", "RAM": 15000, "Disk": 400, "Ephemeral": 0, "VCPUs": 4, "Is Public": true}, {"ID": "24c1f706-3278-4ca7-a773-7df7f999cf14", "Name": "win-eg-60", "RAM": 60000, "Disk": 1600, "Ephemeral": 0, "VCPUs": 16, "Is Public": true}, {"ID": "30b43ca1-131f-4b0d-8087-e03bc99f7ec6", "Name": "sp-120", "RAM": 120000, "Disk": 800, "Ephemeral": 0, "VCPUs": 8, "Is Public": true}, {"ID": "3502c448-8c96-4062-bf78-c5d2ac962e6d", "Name": "win-eg-120", "RAM": 120000, "Disk": 1600, "Ephemeral": 0, "VCPUs": 32, "Is Public": true}, {"ID": "3a9711d2-a4fb-4d2f-a3cd-1972fd53eb5e", "Name": "vps-ssd-3", "RAM": 8000, "Disk": 40, "Ephemeral": 0, "VCPUs": 2, "Is Public": true}, {"ID": "6763bd1b-5d23-4c87-aca7-d46e35d343a4", "Name": "win-eg-7", "RAM": 7000, "Disk": 200, "Ephemeral": 0, "VCPUs": 2, "Is Public": true}, {"ID": "7eacbe7c-5033-4123-8eec-d61bf27359f9", "Name": "win-sp-30", "RAM": 30000, "Disk": 200, "Ephemeral": 0, "VCPUs": 2, "Is Public": true}, {"ID": "8f08b006-a68b-4eed-80cf-36f8212f8d73", "Name": "win-eg-30", "RAM": 30000, "Disk": 800, "Ephemeral": 0, "VCPUs": 8, "Is Public": true}, {"ID": "98c1e679-5f2c-4069-b4da-4a4f7179b758", "Name": "vps-ssd-1", "RAM": 2000, "Disk": 10, "Ephemeral": 0, "VCPUs": 1, "Is Public": true}, {"ID": "a42a6051-16c7-4563-9cca-9c1abf36e460", "Name": "sp-240", "RAM": 240000, "Disk": 1600, "Ephemeral": 0, "VCPUs": 16, "Is Public": true}, {"ID": "b41c89be-7b7d-4ecc-9cd8-bea145bbbd76", "Name": "eg-7", "RAM": 7000, "Disk": 200, "Ephemeral": 0, "VCPUs": 2, "Is Public": true}, {"ID": "b62d1735-774d-4983-9ed6-283c921d29d7", "Name": "eg-30", "RAM": 30000, "Disk": 800, "Ephemeral": 0, "VCPUs": 8, "Is Public": true}, {"ID": "c3d1d22a-03b3-4fa4-bcc4-1dff4e2b2d32", "Name": "vps-ssd-2", "RAM": 4000, "Disk": 20, "Ephemeral": 0, "VCPUs": 1, "Is Public": true}, {"ID": "ccb922b6-04ad-422d-a8bc-7aff1eae6954", "Name": "eg-60", "RAM": 60000, "Disk": 1600, "Ephemeral": 0, "VCPUs": 16, "Is Public": true}]

2015-08-18T19:00:12.644 INFO:teuthology.openstack:sorted flavor = [{u'Name': u'vps-ssd-1', u'RAM': 2000, u'Ephemeral': 0, u'VCPUs': 1, u'Is Public': True, u'Disk': 10, u'ID': u'98c1e679-5f2c-4069-b4da-4a4f7179b758'}, {u'Name': u'vps-ssd-2', u'RAM': 4000, u'Ephemeral': 0, u'VCPUs': 1, u'Is Public': True, u'Disk': 20, u'ID': u'c3d1d22a-03b3-4fa4-bcc4-1dff4e2b2d32'}, {u'Name': u'eg-7', u'RAM': 7000, u'Ephemeral': 0, u'VCPUs': 2, u'Is Public': True, u'Disk': 200, u'ID': u'b41c89be-7b7d-4ecc-9cd8-bea145bbbd76'}, {u'Name': u'vps-ssd-3', u'RAM': 8000, u'Ephemeral': 0, u'VCPUs': 2, u'Is Public': True, u'Disk': 40, u'ID': u'3a9711d2-a4fb-4d2f-a3cd-1972fd53eb5e'}, {u'Name': u'eg-15', u'RAM': 15000, u'Ephemeral': 0, u'VCPUs': 4, u'Is Public': True, u'Disk': 400, u'ID': u'23ec7924-483c-4414-9aaf-bf03575f0bfe'}, {u'Name': u'eg-30', u'RAM': 30000, u'Ephemeral': 0, u'VCPUs': 8, u'Is Public': True, u'Disk': 800, u'ID': u'b62d1735-774d-4983-9ed6-283c921d29d7'}, {u'Name': u'eg-60', u'RAM': 60000, u'Ephemeral': 0, u'VCPUs': 16, u'Is Public': True, u'Disk': 1600, u'ID': u'ccb922b6-04ad-422d-a8bc-7aff1eae6954'}, {u'Name': u'eg-120', u'RAM': 120000, u'Ephemeral': 0, u'VCPUs': 32, u'Is Public': True, u'Disk': 1600, u'ID': u'1e2c13fc-4ba9-4773-a13e-75ce96fb4e96'}]
2015-08-18T19:00:12.644 DEBUG:teuthology.misc:openstack server create -f json --image 'teuthology-centos-7.0' --flavor 'vps-ssd-1' --key-name teuthology --user-data /tmp/tmpmNjCq_ --min 2 --max 2 --security-group teuthology --property teuthology=13aabdf5663d60d735e873a24a924c25 --property ownedby=149.202.169.83 --wait target
2015-08-18T19:01:34.690 DEBUG:teuthology.misc:openstack server create -f json --image 'teuthology-centos-7.0' --flavor 'vps-ssd-1' --key-name teuthology --user-data /tmp/tmpmNjCq_ --min 2 --max 2 --security-group teuthology --property teuthology=13aabdf5663d60d735e873a24a924c25 --property ownedby=149.202.169.83 --wait target output
[{"Field": "OS-DCF:diskConfig", "Value": "MANUAL"}, {"Field": "OS-EXT-AZ:availability_zone", "Value": "nova"}, {"Field": "OS-EXT-STS:power_state", "Value": 1}, {"Field": "OS-EXT-STS:task_state", "Value": null}, {"Field": "OS-EXT-STS:vm_state", "Value": "active"}, {"Field": "OS-SRV-USG:launched_at", "Value": "2015-08-18T19:01:30.000000"}, {"Field": "OS-SRV-USG:terminated_at", "Value": null}, {"Field": "accessIPv4", "Value": ""}, {"Field": "accessIPv6", "Value": ""}, {"Field": "addresses", "Value": "Ext-Net=149.202.170.122"}, {"Field": "adminPass", "Value": "GHomSCq2MbxE"}, {"Field": "config_drive", "Value": ""}, {"Field": "created", "Value": "2015-08-18T19:00:15Z"}, {"Field": "flavor", "Value": "vps-ssd-1 (98c1e679-5f2c-4069-b4da-4a4f7179b758)"}, {"Field": "hostId", "Value": "643dffa5fd86216e17116ac0b2b145e2410835ccdba3e2f75fcc9cd5"}, {"Field": "id", "Value": "26e2cecf-4b16-4689-9cd6-1a1683bd606f"}, {"Field": "image", "Value": "teuthology-centos-7.0 (94967743-087d-44d3-a9bc-1bfe9481127b)"}, {"Field": "key_name", "Value": "teuthology"}, {"Field": "name", "Value": "target-26e2cecf-4b16-4689-9cd6-1a1683bd606f"}, {"Field": "os-extended-volumes:volumes_attached", "Value": []}, {"Field": "progress", "Value": 0}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"Field": "security_groups", "Value": [{"name": "teuthology"}]}, {"Field": "status", "Value": "ACTIVE"}, {"Field": "updated", "Value": "2015-08-18T19:01:30Z"}, {"Field": "user_id", "Value": "3a075820e5d24fda96cd340b87fd94e9"}]

2015-08-18T19:01:34.691 DEBUG:teuthology.misc:openstack server list -f json --long
2015-08-18T19:01:36.121 DEBUG:teuthology.misc:openstack server list -f json --long output [{"ID": "d6613710-423a-4994-93dc-88f0058ee505", "Name": "target-d6613710-423a-4994-93dc-88f0058ee505", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.123", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"ID": "26e2cecf-4b16-4689-9cd6-1a1683bd606f", "Name": "target-26e2cecf-4b16-4689-9cd6-1a1683bd606f", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.122", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"ID": "525337d6-3dde-455e-8057-c50c25fbe43b", "Name": "target170108", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.108", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='7761131ae433c1152049989ac1373416'"}, {"ID": "67c9495c-b744-46bd-805a-d15c45f9852c", "Name": "target170107", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.107", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='7761131ae433c1152049989ac1373416'"}, {"ID": "36d7f91a-b42d-4576-8189-4c7b44f1b8b7", "Name": "target170104", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.104", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='9a6a24f570ced67408c7228c0f92bce1'"}, {"ID": "24373280-994a-4f5e-9778-870d65fc4216", "Name": "target170103", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.103", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='9a6a24f570ced67408c7228c0f92bce1'"}, {"ID": "3dd36b73-f732-4629-8d40-3e69e2b56795", "Name": "target170105", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.105", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='224049b9084114122c2a22e43c05ede3'"}, {"ID": "1512c8a5-61b9-4101-a104-4e1a66575af6", "Name": "target170106", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.106", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='224049b9084114122c2a22e43c05ede3'"}, {"ID": "7b20e6c7-6bfc-4c7c-b400-29f753b9e35c", "Name": "target170101", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.101", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='13ae2cd9b34b5d178b4df4b59b9218bc'"}, {"ID": "166db435-28c2-4159-aec4-86aba5db2834", "Name": "target170102", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.102", "Availability Zone": "nova", "Host": "", "Properties": "ownedby='149.202.169.83', teuthology='13ae2cd9b34b5d178b4df4b59b9218bc'"}, {"ID": "e15522ff-2404-4640-bf69-b5e5674900e1", "Name": "teuthology", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.169.83", "Availability Zone": "nova", "Host": "", "Properties": ""}, {"ID": "018bc993-6944-4428-a057-6c2f3e472a33", "Name": "other", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.161.79", "Availability Zone": "nova", "Host": "", "Properties": ""}]

2015-08-18T19:01:36.122 DEBUG:teuthology.misc:openstack server show -f json d6613710-423a-4994-93dc-88f0058ee505
2015-08-18T19:01:38.231 DEBUG:teuthology.misc:openstack server show -f json d6613710-423a-4994-93dc-88f0058ee505 output [{"Field": "OS-DCF:diskConfig", "Value": "MANUAL"}, {"Field": "OS-EXT-AZ:availability_zone", "Value": "nova"}, {"Field": "OS-EXT-STS:power_state", "Value": 1}, {"Field": "OS-EXT-STS:task_state", "Value": null}, {"Field": "OS-EXT-STS:vm_state", "Value": "active"}, {"Field": "OS-SRV-USG:launched_at", "Value": "2015-08-18T19:01:30.000000"}, {"Field": "OS-SRV-USG:terminated_at", "Value": null}, {"Field": "accessIPv4", "Value": ""}, {"Field": "accessIPv6", "Value": ""}, {"Field": "addresses", "Value": "Ext-Net=149.202.170.123"}, {"Field": "config_drive", "Value": ""}, {"Field": "created", "Value": "2015-08-18T19:00:15Z"}, {"Field": "flavor", "Value": "vps-ssd-1 (98c1e679-5f2c-4069-b4da-4a4f7179b758)"}, {"Field": "hostId", "Value": "643dffa5fd86216e17116ac0b2b145e2410835ccdba3e2f75fcc9cd5"}, {"Field": "id", "Value": "d6613710-423a-4994-93dc-88f0058ee505"}, {"Field": "image", "Value": "teuthology-centos-7.0 (94967743-087d-44d3-a9bc-1bfe9481127b)"}, {"Field": "key_name", "Value": "teuthology"}, {"Field": "name", "Value": "target-d6613710-423a-4994-93dc-88f0058ee505"}, {"Field": "os-extended-volumes:volumes_attached", "Value": []}, {"Field": "progress", "Value": 0}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"Field": "security_groups", "Value": [{"name": "teuthology"}]}, {"Field": "status", "Value": "ACTIVE"}, {"Field": "updated", "Value": "2015-08-18T19:01:30Z"}, {"Field": "user_id", "Value": "3a075820e5d24fda96cd340b87fd94e9"}]

2015-08-18T19:01:38.233 DEBUG:teuthology.misc:openstack server set --name target170123 d6613710-423a-4994-93dc-88f0058ee505
2015-08-18T19:01:39.729 DEBUG:teuthology.misc:openstack server set --name target170123 d6613710-423a-4994-93dc-88f0058ee505 output
2015-08-18T19:01:40.749 INFO:teuthology.misc:try ssh_keyscan again for target170123.teuthology
2015-08-18T19:01:47.769 INFO:teuthology.misc:try ssh_keyscan again for target170123.teuthology
2015-08-18T19:02:08.854 DEBUG:teuthology.openstack:cloud_init_wait target170123.teuthology
2015-08-18T19:02:10.106 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:12.521 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:01:52 localhost cloud-init: nameserver 149.202.169.83
Aug 18 19:01:52 localhost cloud-init: search teuthology
Aug 18 19:01:52 localhost cloud-init: target170123.teuthologyDefaults !requiretty
Aug 18 19:01:52 localhost cloud-init: Defaults visiblepw
Aug 18 19:01:53 localhost cloud-init: Cloud-init v. 0.7.5 running 'modules:config' at Tue, 18 Aug 2015 19:01:53 +0000. Up 19.11 seconds.
Aug 18 19:01:53 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
nameserver 149.202.169.83
search teuthology
target170123.teuthologyDefaults !requiretty
Defaults visiblepw
Cloud-init v. 0.7.5 running 'modules:config' at Tue, 18 Aug 2015 19:01:53 +0000. Up 19.11 seconds.
Loaded plugins: fastestmirror
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:12.521 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:17.951 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:18.324 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:01:52 localhost cloud-init: nameserver 149.202.169.83
Aug 18 19:01:52 localhost cloud-init: search teuthology
Aug 18 19:01:52 localhost cloud-init: target170123.teuthologyDefaults !requiretty
Aug 18 19:01:52 localhost cloud-init: Defaults visiblepw
Aug 18 19:01:53 localhost cloud-init: Cloud-init v. 0.7.5 running 'modules:config' at Tue, 18 Aug 2015 19:01:53 +0000. Up 19.11 seconds.
Aug 18 19:01:53 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
nameserver 149.202.169.83
search teuthology
target170123.teuthologyDefaults !requiretty
Defaults visiblepw
Cloud-init v. 0.7.5 running 'modules:config' at Tue, 18 Aug 2015 19:01:53 +0000. Up 19.11 seconds.
Loaded plugins: fastestmirror
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:18.324 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:21.438 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:21.788 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:01:52 localhost cloud-init: nameserver 149.202.169.83
Aug 18 19:01:52 localhost cloud-init: search teuthology
Aug 18 19:01:52 localhost cloud-init: target170123.teuthologyDefaults !requiretty
Aug 18 19:01:52 localhost cloud-init: Defaults visiblepw
Aug 18 19:01:53 localhost cloud-init: Cloud-init v. 0.7.5 running 'modules:config' at Tue, 18 Aug 2015 19:01:53 +0000. Up 19.11 seconds.
Aug 18 19:01:53 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
nameserver 149.202.169.83
search teuthology
target170123.teuthologyDefaults !requiretty
Defaults visiblepw
Cloud-init v. 0.7.5 running 'modules:config' at Tue, 18 Aug 2015 19:01:53 +0000. Up 19.11 seconds.
Loaded plugins: fastestmirror
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:21.789 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:24.520 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:24.663 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org
Aug 18 19:02:22 localhost cloud-init: Metadata Cache Created
Aug 18 19:02:22 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:22 localhost cloud-init: Loading mirror speeds from cached hostfile
Aug 18 19:02:22 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org
Metadata Cache Created
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:24.663 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:27.438 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:27.564 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org
Aug 18 19:02:22 localhost cloud-init: Metadata Cache Created
Aug 18 19:02:22 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:22 localhost cloud-init: Loading mirror speeds from cached hostfile
Aug 18 19:02:22 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org
Metadata Cache Created
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:27.565 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:30.325 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:30.465 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org
Aug 18 19:02:22 localhost cloud-init: Metadata Cache Created
Aug 18 19:02:22 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:22 localhost cloud-init: Loading mirror speeds from cached hostfile
Aug 18 19:02:22 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org
Metadata Cache Created
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:30.466 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:33.284 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:35.731 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:07 localhost cloud-init: Determining fastest mirrors
Aug 18 19:02:07 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:07 localhost cloud-init: * updates: centos.crazyfrogs.org
Aug 18 19:02:22 localhost cloud-init: Metadata Cache Created
Aug 18 19:02:22 localhost cloud-init: Loaded plugins: fastestmirror
Aug 18 19:02:22 localhost cloud-init: Loading mirror speeds from cached hostfile
Aug 18 19:02:22 localhost cloud-init: * base: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * extras: centos.quelquesmots.fr
Aug 18 19:02:22 localhost cloud-init: * updates: centos.crazyfrogs.org

==> /var/log/cloud-init-output.log <==
Determining fastest mirrors
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org
Metadata Cache Created
Loaded plugins: fastestmirror
Loading mirror speeds from cached hostfile
* base: centos.quelquesmots.fr
* extras: centos.quelquesmots.fr
* updates: centos.crazyfrogs.org

2015-08-18T19:02:35.732 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:38.629 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:39.106 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:36 localhost cloud-init: Transaction Summary
Aug 18 19:02:36 localhost cloud-init: ================================================================================
Aug 18 19:02:36 localhost cloud-init: Install 3 Packages (+33 Dependent packages)
Aug 18 19:02:36 localhost cloud-init: Upgrade 1 Package (+ 1 Dependent package)
Aug 18 19:02:36 localhost cloud-init: Total download size: 23 M
Aug 18 19:02:36 localhost cloud-init: Downloading packages:
Aug 18 19:02:37 localhost cloud-init: Delta RPMs disabled because /usr/bin/applydeltarpm not installed.
Aug 18 19:02:37 localhost cloud-init: warning: /var/cache/yum/x86_64/7/base/packages/autogen-libopts-5.18-5.el7.x86_64.rpm: Header V3 RSA/SHA256 Signature, key ID f4a80eb5: NOKEY
Aug 18 19:02:37 localhost cloud-init: Public key for autogen-libopts-5.18-5.el7.x86_64.rpm is not installed
Aug 18 19:02:37 localhost cloud-init: Public key for ntpdate-4.2.6p5-19.el7.centos.1.x86_64.rpm is not installed

==> /var/log/cloud-init-output.log <==
================================================================================
Install 3 Packages (+33 Dependent packages)
Upgrade 1 Package (+ 1 Dependent package)

Total download size: 23 M
Downloading packages:
Delta RPMs disabled because /usr/bin/applydeltarpm not installed.
warning: /var/cache/yum/x86_64/7/base/packages/autogen-libopts-5.18-5.el7.x86_64.rpm: Header V3 RSA/SHA256 Signature, key ID f4a80eb5: NOKEY
Public key for autogen-libopts-5.18-5.el7.x86_64.rpm is not installed
Public key for ntpdate-4.2.6p5-19.el7.centos.1.x86_64.rpm is not installed

2015-08-18T19:02:39.106 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:41.824 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:41.982 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:40 localhost cloud-init: Installing : 1:perl-parent-0.225-244.el7.noarch 1/40
Aug 18 19:02:40 localhost cloud-init: Installing : perl-HTTP-Tiny-0.033-3.el7.noarch 2/40
Aug 18 19:02:40 localhost cloud-init: Installing : perl-podlators-2.5.1-3.el7.noarch 3/40
Aug 18 19:02:40 localhost cloud-init: Installing : perl-Pod-Perldoc-3.20-4.el7.noarch 4/40
Aug 18 19:02:41 localhost cloud-init: Installing : 1:perl-Pod-Escapes-1.04-285.el7.noarch 5/40
Aug 18 19:02:41 localhost cloud-init: Installing : perl-Encode-2.51-7.el7.x86_64 6/40
Aug 18 19:02:41 localhost cloud-init: Installing : perl-Text-ParseWords-3.29-4.el7.noarch 7/40
Aug 18 19:02:41 localhost cloud-init: Installing : perl-Pod-Usage-1.63-3.el7.noarch 8/40
Aug 18 19:02:41 localhost cloud-init: Installing : perl-Exporter-5.68-3.el7.noarch 9/40
Aug 18 19:02:41 localhost cloud-init: Installing : perl-constant-1.27-2.el7.noarch 10/40

==> /var/log/cloud-init-output.log <==
Installing : perl-HTTP-Tiny-0.033-3.el7.noarch 2/40
Installing : perl-podlators-2.5.1-3.el7.noarch 3/40
Installing : perl-Pod-Perldoc-3.20-4.el7.noarch 4/40
Installing : 1:perl-Pod-Escapes-1.04-285.el7.noarch 5/40
Installing : perl-Encode-2.51-7.el7.x86_64 6/40
Installing : perl-Text-ParseWords-3.29-4.el7.noarch 7/40
Installing : perl-Pod-Usage-1.63-3.el7.noarch 8/40
Installing : perl-Exporter-5.68-3.el7.noarch 9/40
Installing : perl-constant-1.27-2.el7.noarch 10/40
Installing : perl-Time-Local-1.2300-2.el7.noarch 11/40
2015-08-18T19:02:41.982 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:44.733 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:45.135 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:42 localhost cloud-init: Installing : perl-Scalar-List-Utils-1.27-248.el7.x86_64 16/40
Aug 18 19:02:42 localhost cloud-init: Installing : 4:perl-macros-5.16.3-285.el7.x86_64 17/40
Aug 18 19:02:42 localhost cloud-init: Installing : 1:perl-Pod-Simple-3.28-4.el7.noarch 18/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-Storable-2.45-3.el7.x86_64 19/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-File-Temp-0.23.01-3.el7.noarch 20/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-File-Path-2.09-2.el7.noarch 21/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-threads-shared-1.43-6.el7.x86_64 22/40
Aug 18 19:02:43 localhost cloud-init: Installing : perl-threads-1.87-4.el7.x86_64 23/40
Aug 18 19:02:43 localhost cloud-init: Installing : perl-Filter-1.49-3.el7.x86_64 24/40
Aug 18 19:02:43 localhost cloud-init: Installing : 4:perl-libs-5.16.3-285.el7.x86_64 25/40

==> /var/log/cloud-init-output.log <==
Installing : 4:perl-macros-5.16.3-285.el7.x86_64 17/40
Installing : 1:perl-Pod-Simple-3.28-4.el7.noarch 18/40
Installing : perl-Storable-2.45-3.el7.x86_64 19/40
Installing : perl-File-Temp-0.23.01-3.el7.noarch 20/40
Installing : perl-File-Path-2.09-2.el7.noarch 21/40
Installing : perl-threads-shared-1.43-6.el7.x86_64 22/40
Installing : perl-threads-1.87-4.el7.x86_64 23/40
Installing : perl-Filter-1.49-3.el7.x86_64 24/40
Installing : 4:perl-libs-5.16.3-285.el7.x86_64 25/40
Installing : perl-Getopt-Long-2.40-2.el7.noarch 26/40
2015-08-18T19:02:45.136 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:47.888 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:48.280 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:42 localhost cloud-init: Installing : perl-Storable-2.45-3.el7.x86_64 19/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-File-Temp-0.23.01-3.el7.noarch 20/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-File-Path-2.09-2.el7.noarch 21/40
Aug 18 19:02:42 localhost cloud-init: Installing : perl-threads-shared-1.43-6.el7.x86_64 22/40
Aug 18 19:02:43 localhost cloud-init: Installing : perl-threads-1.87-4.el7.x86_64 23/40
Aug 18 19:02:43 localhost cloud-init: Installing : perl-Filter-1.49-3.el7.x86_64 24/40
Aug 18 19:02:43 localhost cloud-init: Installing : 4:perl-libs-5.16.3-285.el7.x86_64 25/40
Aug 18 19:02:46 localhost cloud-init: Installing : perl-Getopt-Long-2.40-2.el7.noarch 26/40
Aug 18 19:02:46 localhost cloud-init: Installing : 4:perl-5.16.3-285.el7.x86_64 27/40
Aug 18 19:02:47 localhost cloud-init: Installing : 1:perl-Error-0.17020-2.el7.noarch 28/40

==> /var/log/cloud-init-output.log <==
Installing : perl-File-Temp-0.23.01-3.el7.noarch 20/40
Installing : perl-File-Path-2.09-2.el7.noarch 21/40
Installing : perl-threads-shared-1.43-6.el7.x86_64 22/40
Installing : perl-threads-1.87-4.el7.x86_64 23/40
Installing : perl-Filter-1.49-3.el7.x86_64 24/40
Installing : 4:perl-libs-5.16.3-285.el7.x86_64 25/40
Installing : perl-Getopt-Long-2.40-2.el7.noarch 26/40
Installing : 4:perl-5.16.3-285.el7.x86_64 27/40
Installing : 1:perl-Error-0.17020-2.el7.noarch 28/40
Installing : perl-TermReadKey-2.30-20.el7.x86_64 29/40
2015-08-18T19:02:48.280 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:51.052 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:51.388 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:43 localhost cloud-init: Installing : perl-threads-1.87-4.el7.x86_64 23/40
Aug 18 19:02:43 localhost cloud-init: Installing : perl-Filter-1.49-3.el7.x86_64 24/40
Aug 18 19:02:43 localhost cloud-init: Installing : 4:perl-libs-5.16.3-285.el7.x86_64 25/40
Aug 18 19:02:46 localhost cloud-init: Installing : perl-Getopt-Long-2.40-2.el7.noarch 26/40
Aug 18 19:02:46 localhost cloud-init: Installing : 4:perl-5.16.3-285.el7.x86_64 27/40
Aug 18 19:02:47 localhost cloud-init: Installing : 1:perl-Error-0.17020-2.el7.noarch 28/40
Aug 18 19:02:49 localhost cloud-init: Installing : perl-TermReadKey-2.30-20.el7.x86_64 29/40
Aug 18 19:02:49 localhost cloud-init: Updating : python-libs-2.7.5-18.el7_1.1.x86_64 30/40
Aug 18 19:02:49 localhost cloud-init: Updating : python-2.7.5-18.el7_1.1.x86_64 31/40
Aug 18 19:02:50 localhost cloud-init: Installing : libgnome-keyring-3.8.0-3.el7.x86_64 32/40

==> /var/log/cloud-init-output.log <==
Installing : perl-Filter-1.49-3.el7.x86_64 24/40
Installing : 4:perl-libs-5.16.3-285.el7.x86_64 25/40
Installing : perl-Getopt-Long-2.40-2.el7.noarch 26/40
Installing : 4:perl-5.16.3-285.el7.x86_64 27/40
Installing : 1:perl-Error-0.17020-2.el7.noarch 28/40
Installing : perl-TermReadKey-2.30-20.el7.x86_64 29/40
Updating : python-libs-2.7.5-18.el7_1.1.x86_64 30/40
Updating : python-2.7.5-18.el7_1.1.x86_64 31/40
Installing : libgnome-keyring-3.8.0-3.el7.x86_64 32/40
Installing : perl-Git-1.8.3.1-4.el7.noarch 33/40
2015-08-18T19:02:51.388 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:54.127 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:54.289 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:53 localhost cloud-init: Verifying : libgnome-keyring-3.8.0-3.el7.x86_64 27/40
Aug 18 19:02:53 localhost cloud-init: Verifying : ntp-4.2.6p5-19.el7.centos.1.x86_64 28/40
Aug 18 19:02:53 localhost cloud-init: Verifying : perl-Encode-2.51-7.el7.x86_64 29/40
Aug 18 19:02:53 localhost cloud-init: Verifying : perl-Storable-2.45-3.el7.x86_64 30/40
Aug 18 19:02:53 localhost cloud-init: Verifying : 4:perl-5.16.3-285.el7.x86_64 31/40
Aug 18 19:02:53 localhost cloud-init: Verifying : perl-Getopt-Long-2.40-2.el7.noarch 32/40
Aug 18 19:02:54 localhost cloud-init: Verifying : perl-File-Path-2.09-2.el7.noarch 33/40
Aug 18 19:02:54 localhost cloud-init: Verifying : perl-threads-1.87-4.el7.x86_64 34/40
Aug 18 19:02:54 localhost cloud-init: Verifying : python-libs-2.7.5-18.el7_1.1.x86_64 35/40
Aug 18 19:02:54 localhost cloud-init: Verifying : perl-Filter-1.49-3.el7.x86_64 36/40

==> /var/log/cloud-init-output.log <==
Verifying : ntp-4.2.6p5-19.el7.centos.1.x86_64 28/40
Verifying : perl-Encode-2.51-7.el7.x86_64 29/40
Verifying : perl-Storable-2.45-3.el7.x86_64 30/40
Verifying : 4:perl-5.16.3-285.el7.x86_64 31/40
Verifying : perl-Getopt-Long-2.40-2.el7.noarch 32/40
Verifying : perl-File-Path-2.09-2.el7.noarch 33/40
Verifying : perl-threads-1.87-4.el7.x86_64 34/40
Verifying : python-libs-2.7.5-18.el7_1.1.x86_64 35/40
Verifying : perl-Filter-1.49-3.el7.x86_64 36/40
Verifying : perl-Text-ParseWords-3.29-4.el7.noarch 37/40
2015-08-18T19:02:54.290 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:56.980 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:57.125 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:54 localhost cloud-init: perl-podlators.noarch 0:2.5.1-3.el7
Aug 18 19:02:54 localhost cloud-init: perl-threads.x86_64 0:1.87-4.el7
Aug 18 19:02:54 localhost cloud-init: perl-threads-shared.x86_64 0:1.43-6.el7
Aug 18 19:02:54 localhost cloud-init: Updated:
Aug 18 19:02:54 localhost cloud-init: python.x86_64 0:2.7.5-18.el7_1.1
Aug 18 19:02:54 localhost cloud-init: Dependency Updated:
Aug 18 19:02:54 localhost cloud-init: python-libs.x86_64 0:2.7.5-18.el7_1.1
Aug 18 19:02:54 localhost cloud-init: Complete!
Aug 18 19:02:54 localhost cloud-init: Cloud-init v. 0.7.5 running 'modules:final' at Tue, 18 Aug 2015 19:02:54 +0000. Up 80.41 seconds.
Aug 18 19:02:54 localhost cloud-init: The system is finally up, after 80.55 seconds

==> /var/log/cloud-init-output.log <==

Updated:
python.x86_64 0:2.7.5-18.el7_1.1

Dependency Updated:
python-libs.x86_64 0:2.7.5-18.el7_1.1

Complete!
Cloud-init v. 0.7.5 running 'modules:final' at Tue, 18 Aug 2015 19:02:54 +0000. Up 80.41 seconds.
The system is finally up, after 80.55 seconds
/var/log/cloud-init.log:Aug 18 19:02:54 localhost cloud-init: The system is finally up, after 80.55 seconds
/var/log/cloud-init-output.log:The system is finally up, after 80.55 seconds

2015-08-18T19:02:57.126 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:02:57.127 DEBUG:teuthology.misc:openstack volume show -f json target170123-0
2015-08-18T19:02:58.406 ERROR:teuthology.misc:openstack volume show -f json target170123-0 error ERROR: openstack No volume with a name or ID of 'target170123-0' exists.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/misc.py", line 1309, in sh
shell=True)
File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'openstack volume show -f json target170123-0' returned non-zero exit status 1
2015-08-18T19:02:58.407 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170123-0
2015-08-18T19:02:59.638 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170123-0 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:02:59.481919"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170123-0"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "3bd7faab-8d4f-4096-bf68-5c4d867160e0"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "creating"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:02:59.638 DEBUG:teuthology.misc:openstack volume show -f json target170123-0
2015-08-18T19:03:00.969 DEBUG:teuthology.misc:openstack volume show -f json target170123-0 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:02:59.000000"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170123-0"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "3bd7faab-8d4f-4096-bf68-5c4d867160e0"}, {"Field": "os-volume-replication:driver_data", "Value": null}, {"Field": "os-volume-replication:extended_status", "Value": null}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "available"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:00.970 DEBUG:teuthology.misc:openstack server add volume target170123 target170123-0
2015-08-18T19:03:03.221 DEBUG:teuthology.misc:openstack server add volume target170123 target170123-0 output
2015-08-18T19:03:03.221 DEBUG:teuthology.misc:openstack volume show -f json target170123-1
2015-08-18T19:03:04.529 ERROR:teuthology.misc:openstack volume show -f json target170123-1 error ERROR: openstack No volume with a name or ID of 'target170123-1' exists.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/misc.py", line 1309, in sh
shell=True)
File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'openstack volume show -f json target170123-1' returned non-zero exit status 1
2015-08-18T19:03:04.530 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170123-1
2015-08-18T19:03:05.630 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170123-1 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:05.464881"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170123-1"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "1d720c05-7817-4be9-9d77-86578bb0855a"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "creating"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:05.631 DEBUG:teuthology.misc:openstack volume show -f json target170123-1
2015-08-18T19:03:07.046 DEBUG:teuthology.misc:openstack volume show -f json target170123-1 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:05.000000"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170123-1"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "1d720c05-7817-4be9-9d77-86578bb0855a"}, {"Field": "os-volume-replication:driver_data", "Value": null}, {"Field": "os-volume-replication:extended_status", "Value": null}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "available"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:07.047 DEBUG:teuthology.misc:openstack server add volume target170123 target170123-1
2015-08-18T19:03:09.353 DEBUG:teuthology.misc:openstack server add volume target170123 target170123-1 output
2015-08-18T19:03:09.353 DEBUG:teuthology.misc:openstack volume show -f json target170123-2
2015-08-18T19:03:10.646 ERROR:teuthology.misc:openstack volume show -f json target170123-2 error ERROR: openstack No volume with a name or ID of 'target170123-2' exists.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/misc.py", line 1309, in sh
shell=True)
File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'openstack volume show -f json target170123-2' returned non-zero exit status 1
2015-08-18T19:03:10.647 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170123-2
2015-08-18T19:03:11.828 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170123-2 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:11.660011"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170123-2"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "e8432272-a4f8-46a1-979c-ecae56fbca89"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "creating"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:11.828 DEBUG:teuthology.misc:openstack volume show -f json target170123-2
2015-08-18T19:03:13.254 DEBUG:teuthology.misc:openstack volume show -f json target170123-2 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:11.000000"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170123-2"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "e8432272-a4f8-46a1-979c-ecae56fbca89"}, {"Field": "os-volume-replication:driver_data", "Value": null}, {"Field": "os-volume-replication:extended_status", "Value": null}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "available"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:13.255 DEBUG:teuthology.misc:openstack server add volume target170123 target170123-2
2015-08-18T19:03:15.482 DEBUG:teuthology.misc:openstack server add volume target170123 target170123-2 output
2015-08-18T19:03:15.483 DEBUG:teuthology.misc:openstack server show -f json 26e2cecf-4b16-4689-9cd6-1a1683bd606f
2015-08-18T19:03:17.391 DEBUG:teuthology.misc:openstack server show -f json 26e2cecf-4b16-4689-9cd6-1a1683bd606f output [{"Field": "OS-DCF:diskConfig", "Value": "MANUAL"}, {"Field": "OS-EXT-AZ:availability_zone", "Value": "nova"}, {"Field": "OS-EXT-STS:power_state", "Value": 1}, {"Field": "OS-EXT-STS:task_state", "Value": null}, {"Field": "OS-EXT-STS:vm_state", "Value": "active"}, {"Field": "OS-SRV-USG:launched_at", "Value": "2015-08-18T19:01:30.000000"}, {"Field": "OS-SRV-USG:terminated_at", "Value": null}, {"Field": "accessIPv4", "Value": ""}, {"Field": "accessIPv6", "Value": ""}, {"Field": "addresses", "Value": "Ext-Net=149.202.170.122"}, {"Field": "config_drive", "Value": ""}, {"Field": "created", "Value": "2015-08-18T19:00:15Z"}, {"Field": "flavor", "Value": "vps-ssd-1 (98c1e679-5f2c-4069-b4da-4a4f7179b758)"}, {"Field": "hostId", "Value": "643dffa5fd86216e17116ac0b2b145e2410835ccdba3e2f75fcc9cd5"}, {"Field": "id", "Value": "26e2cecf-4b16-4689-9cd6-1a1683bd606f"}, {"Field": "image", "Value": "teuthology-centos-7.0 (94967743-087d-44d3-a9bc-1bfe9481127b)"}, {"Field": "key_name", "Value": "teuthology"}, {"Field": "name", "Value": "target-26e2cecf-4b16-4689-9cd6-1a1683bd606f"}, {"Field": "os-extended-volumes:volumes_attached", "Value": []}, {"Field": "progress", "Value": 0}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"Field": "security_groups", "Value": [{"name": "teuthology"}]}, {"Field": "status", "Value": "ACTIVE"}, {"Field": "updated", "Value": "2015-08-18T19:01:30Z"}, {"Field": "user_id", "Value": "3a075820e5d24fda96cd340b87fd94e9"}]

2015-08-18T19:03:17.392 DEBUG:teuthology.misc:openstack server set --name target170122 26e2cecf-4b16-4689-9cd6-1a1683bd606f
2015-08-18T19:03:18.876 DEBUG:teuthology.misc:openstack server set --name target170122 26e2cecf-4b16-4689-9cd6-1a1683bd606f output
2015-08-18T19:03:33.956 DEBUG:teuthology.openstack:cloud_init_wait target170122.teuthology
2015-08-18T19:03:34.714 DEBUG:teuthology.openstack:cloud_init_wait tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:03:34.887 DEBUG:teuthology.openstack:cloud_init_wait stdout tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log ==> /var/log/cloud-init.log <==
Aug 18 19:02:52 localhost cloud-init: perl-podlators.noarch 0:2.5.1-3.el7
Aug 18 19:02:52 localhost cloud-init: perl-threads.x86_64 0:1.87-4.el7
Aug 18 19:02:52 localhost cloud-init: perl-threads-shared.x86_64 0:1.43-6.el7
Aug 18 19:02:52 localhost cloud-init: Updated:
Aug 18 19:02:52 localhost cloud-init: python.x86_64 0:2.7.5-18.el7_1.1
Aug 18 19:02:52 localhost cloud-init: Dependency Updated:
Aug 18 19:02:52 localhost cloud-init: python-libs.x86_64 0:2.7.5-18.el7_1.1
Aug 18 19:02:52 localhost cloud-init: Complete!
Aug 18 19:02:53 localhost cloud-init: Cloud-init v. 0.7.5 running 'modules:final' at Tue, 18 Aug 2015 19:02:53 +0000. Up 77.72 seconds.
Aug 18 19:02:53 localhost cloud-init: The system is finally up, after 77.93 seconds

==> /var/log/cloud-init-output.log <==

Updated:
python.x86_64 0:2.7.5-18.el7_1.1

Dependency Updated:
python-libs.x86_64 0:2.7.5-18.el7_1.1

Complete!
Cloud-init v. 0.7.5 running 'modules:final' at Tue, 18 Aug 2015 19:02:53 +0000. Up 77.72 seconds.
The system is finally up, after 77.93 seconds
/var/log/cloud-init.log:Aug 18 19:02:53 localhost cloud-init: The system is finally up, after 77.93 seconds
/var/log/cloud-init-output.log:The system is finally up, after 77.93 seconds

2015-08-18T19:03:34.890 DEBUG:teuthology.openstack:cloud_init_wait stderr tail /var/log/cloud-init*.log ; test -f /tmp/init.out && tail /tmp/init.out ; grep 'The system is finally up' /var/log/cloud-init*.log
2015-08-18T19:03:34.891 DEBUG:teuthology.misc:openstack volume show -f json target170122-0
2015-08-18T19:03:36.377 ERROR:teuthology.misc:openstack volume show -f json target170122-0 error ERROR: openstack No volume with a name or ID of 'target170122-0' exists.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/misc.py", line 1309, in sh
shell=True)
File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'openstack volume show -f json target170122-0' returned non-zero exit status 1
2015-08-18T19:03:36.377 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170122-0
2015-08-18T19:03:37.692 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170122-0 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:37.527502"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170122-0"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "bbe65cd7-0530-4929-ab86-b0236cb6ef6b"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "creating"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:37.692 DEBUG:teuthology.misc:openstack volume show -f json target170122-0
2015-08-18T19:03:38.894 DEBUG:teuthology.misc:openstack volume show -f json target170122-0 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:37.000000"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170122-0"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "bbe65cd7-0530-4929-ab86-b0236cb6ef6b"}, {"Field": "os-volume-replication:driver_data", "Value": null}, {"Field": "os-volume-replication:extended_status", "Value": null}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "available"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:38.895 DEBUG:teuthology.misc:openstack server add volume target170122 target170122-0
2015-08-18T19:03:41.096 DEBUG:teuthology.misc:openstack server add volume target170122 target170122-0 output
2015-08-18T19:03:41.097 DEBUG:teuthology.misc:openstack volume show -f json target170122-1
2015-08-18T19:03:42.466 ERROR:teuthology.misc:openstack volume show -f json target170122-1 error ERROR: openstack No volume with a name or ID of 'target170122-1' exists.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/misc.py", line 1309, in sh
shell=True)
File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'openstack volume show -f json target170122-1' returned non-zero exit status 1
2015-08-18T19:03:42.466 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170122-1
2015-08-18T19:03:43.766 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170122-1 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:43.607625"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170122-1"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "7f6246dd-89fb-4239-b608-a766e4af0de2"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "creating"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:43.767 DEBUG:teuthology.misc:openstack volume show -f json target170122-1
2015-08-18T19:03:45.087 DEBUG:teuthology.misc:openstack volume show -f json target170122-1 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:43.000000"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170122-1"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "7f6246dd-89fb-4239-b608-a766e4af0de2"}, {"Field": "os-volume-replication:driver_data", "Value": null}, {"Field": "os-volume-replication:extended_status", "Value": null}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "available"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:45.087 DEBUG:teuthology.misc:openstack server add volume target170122 target170122-1
2015-08-18T19:03:47.190 DEBUG:teuthology.misc:openstack server add volume target170122 target170122-1 output
2015-08-18T19:03:47.190 DEBUG:teuthology.misc:openstack volume show -f json target170122-2
2015-08-18T19:03:48.526 ERROR:teuthology.misc:openstack volume show -f json target170122-2 error ERROR: openstack No volume with a name or ID of 'target170122-2' exists.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/misc.py", line 1309, in sh
shell=True)
File "/usr/lib/python2.7/subprocess.py", line 573, in check_output
raise CalledProcessError(retcode, cmd, output=output)
CalledProcessError: Command 'openstack volume show -f json target170122-2' returned non-zero exit status 1
2015-08-18T19:03:48.528 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170122-2
2015-08-18T19:03:49.748 DEBUG:teuthology.misc:openstack volume create -f json --size 10 target170122-2 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:49.589305"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170122-2"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "b15f45da-dd66-4ddd-a8dd-e127737cee33"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "creating"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:49.748 DEBUG:teuthology.misc:openstack volume show -f json target170122-2
2015-08-18T19:03:50.911 DEBUG:teuthology.misc:openstack volume show -f json target170122-2 output [{"Field": "attachments", "Value": []}, {"Field": "availability_zone", "Value": "nova"}, {"Field": "bootable", "Value": "false"}, {"Field": "created_at", "Value": "2015-08-18T19:03:49.000000"}, {"Field": "display_description", "Value": null}, {"Field": "display_name", "Value": "target170122-2"}, {"Field": "encrypted", "Value": false}, {"Field": "id", "Value": "b15f45da-dd66-4ddd-a8dd-e127737cee33"}, {"Field": "os-volume-replication:driver_data", "Value": null}, {"Field": "os-volume-replication:extended_status", "Value": null}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": ""}, {"Field": "size", "Value": 10}, {"Field": "snapshot_id", "Value": null}, {"Field": "source_volid", "Value": null}, {"Field": "status", "Value": "available"}, {"Field": "type", "Value": "classic"}]

2015-08-18T19:03:50.912 DEBUG:teuthology.misc:openstack server add volume target170122 target170122-2
2015-08-18T19:03:53.232 DEBUG:teuthology.misc:openstack server add volume target170122 target170122-2 output
2015-08-18T19:03:53.262 DEBUG:teuthology.lock:locked target170123.teuthology as scheduled_ubuntu@teuthology
2015-08-18T19:03:53.285 DEBUG:teuthology.lock:locked target170122.teuthology as scheduled_ubuntu@teuthology
2015-08-18T19:03:53.285 INFO:teuthology.task.internal:2 openstack machines locked this try, 2/2 locked so far
2015-08-18T19:03:53.286 INFO:teuthology.task.internal:Locked targets:
target170122.teuthology: null
target170123.teuthology: null
2015-08-18T19:03:53.287 DEBUG:teuthology.report:Pushing job info to http://localhost:8080/
2015-08-18T19:03:53.336 INFO:teuthology.run_tasks:Running task internal.save_config...
2015-08-18T19:03:53.336 INFO:teuthology.task.internal:Saving configuration
2015-08-18T19:03:53.350 INFO:teuthology.run_tasks:Running task internal.check_lock...
2015-08-18T19:03:53.351 INFO:teuthology.task.internal:Checking locks...
2015-08-18T19:03:53.368 DEBUG:teuthology.task.internal:machine status is {u'is_vm': True, u'locked': True, u'locked_since': u'2015-08-18 19:03:53.269360', u'locked_by': u'scheduled_ubuntu@teuthology', u'up': True, u'mac_address': None, u'name': u'target170122.teuthology', u'os_version': None, u'machine_type': u'openstack', u'vm_host': None, u'os_type': None, u'arch': None, u'ssh_pub_key': None, u'description': u'/usr/share/nginx/html/ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack/22'}
2015-08-18T19:03:53.384 DEBUG:teuthology.task.internal:machine status is {u'is_vm': True, u'locked': True, u'locked_since': u'2015-08-18 19:03:53.248128', u'locked_by': u'scheduled_ubuntu@teuthology', u'up': True, u'mac_address': None, u'name': u'target170123.teuthology', u'os_version': None, u'machine_type': u'openstack', u'vm_host': None, u'os_type': None, u'arch': None, u'ssh_pub_key': None, u'description': u'/usr/share/nginx/html/ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack/22'}
2015-08-18T19:03:53.384 INFO:teuthology.run_tasks:Running task internal.add_remotes...
2015-08-18T19:03:53.385 INFO:teuthology.task.internal:roles: ubuntu@target170122.teuthology - ['mon.a', 'mds.0', 'osd.0']
2015-08-18T19:03:53.385 INFO:teuthology.task.internal:roles: ubuntu@target170123.teuthology - ['osd.1', 'mon.b', 'client.0']
2015-08-18T19:03:53.385 INFO:teuthology.run_tasks:Running task internal.connect...
2015-08-18T19:03:53.385 INFO:teuthology.task.internal:Opening connections...
2015-08-18T19:03:53.385 DEBUG:teuthology.task.internal:connecting to ubuntu@target170123.teuthology
2015-08-18T19:03:53.386 INFO:teuthology.orchestra.connection:{'username': 'ubuntu', 'hostname': 'target170123.teuthology', 'timeout': 60}
2015-08-18T19:03:54.080 DEBUG:teuthology.task.internal:connecting to ubuntu@target170122.teuthology
2015-08-18T19:03:54.080 INFO:teuthology.orchestra.connection:{'username': 'ubuntu', 'hostname': 'target170122.teuthology', 'timeout': 60}
2015-08-18T19:03:54.765 INFO:teuthology.run_tasks:Running task internal.push_inventory...
2015-08-18T19:03:54.765 INFO:teuthology.orchestra.run.target170123:Running: 'uname -m'
2015-08-18T19:03:54.795 INFO:teuthology.orchestra.run.target170123:Running: "python -c 'import platform; print platform.linux_distribution()'"
2015-08-18T19:03:54.900 INFO:teuthology.lock:Updating target170123.teuthology on lock server
2015-08-18T19:03:54.915 INFO:teuthology.orchestra.run.target170122:Running: 'uname -m'
2015-08-18T19:03:54.944 INFO:teuthology.orchestra.run.target170122:Running: "python -c 'import platform; print platform.linux_distribution()'"
2015-08-18T19:03:55.048 INFO:teuthology.lock:Updating target170122.teuthology on lock server
2015-08-18T19:03:55.066 INFO:teuthology.run_tasks:Running task internal.serialize_remote_roles...
2015-08-18T19:03:55.074 INFO:teuthology.run_tasks:Running task internal.check_conflict...
2015-08-18T19:03:55.074 INFO:teuthology.task.internal:Checking for old test directory...
2015-08-18T19:03:55.075 INFO:teuthology.orchestra.run.target170122:Running: "test '!' -e /home/ubuntu/cephtest"
2015-08-18T19:03:55.095 INFO:teuthology.orchestra.run.target170123:Running: "test '!' -e /home/ubuntu/cephtest"
2015-08-18T19:03:55.114 INFO:teuthology.run_tasks:Running task internal.check_ceph_data...
2015-08-18T19:03:55.115 INFO:teuthology.task.internal:Checking for old /var/lib/ceph...
2015-08-18T19:03:55.115 INFO:teuthology.orchestra.run.target170122:Running: "test '!' -e /var/lib/ceph"
2015-08-18T19:03:55.185 INFO:teuthology.orchestra.run.target170123:Running: "test '!' -e /var/lib/ceph"
2015-08-18T19:03:55.205 INFO:teuthology.run_tasks:Running task internal.vm_setup...
2015-08-18T19:03:55.205 INFO:teuthology.run_tasks:Running task internal.base...
2015-08-18T19:03:55.206 INFO:teuthology.task.internal:Creating test directory...
2015-08-18T19:03:55.206 INFO:teuthology.orchestra.run.target170122:Running: 'mkdir -p -m0755 -- /home/ubuntu/cephtest'
2015-08-18T19:03:55.275 INFO:teuthology.orchestra.run.target170123:Running: 'mkdir -p -m0755 -- /home/ubuntu/cephtest'
2015-08-18T19:03:55.299 INFO:teuthology.run_tasks:Running task internal.archive...
2015-08-18T19:03:55.300 INFO:teuthology.task.internal:Creating archive directory...
2015-08-18T19:03:55.301 INFO:teuthology.orchestra.run.target170122:Running: 'install -d -m0755 -- /home/ubuntu/cephtest/archive'
2015-08-18T19:03:55.337 INFO:teuthology.orchestra.run.target170123:Running: 'install -d -m0755 -- /home/ubuntu/cephtest/archive'
2015-08-18T19:03:55.356 INFO:teuthology.run_tasks:Running task internal.coredump...
2015-08-18T19:03:55.356 INFO:teuthology.task.internal:Enabling coredump saving...
2015-08-18T19:03:55.357 INFO:teuthology.orchestra.run.target170122:Running: 'install -d -m0755 -- /home/ubuntu/cephtest/archive/coredump && sudo sysctl -w kernel.core_pattern=/home/ubuntu/cephtest/archive/coredump/%t.%p.core'
2015-08-18T19:03:55.426 INFO:teuthology.orchestra.run.target170123:Running: 'install -d -m0755 -- /home/ubuntu/cephtest/archive/coredump && sudo sysctl -w kernel.core_pattern=/home/ubuntu/cephtest/archive/coredump/%t.%p.core'
2015-08-18T19:03:55.462 INFO:teuthology.orchestra.run.target170122.stdout:kernel.core_pattern = /home/ubuntu/cephtest/archive/coredump/%t.%p.core
2015-08-18T19:03:55.466 INFO:teuthology.orchestra.run.target170123.stdout:kernel.core_pattern = /home/ubuntu/cephtest/archive/coredump/%t.%p.core
2015-08-18T19:03:55.468 INFO:teuthology.run_tasks:Running task internal.archive_upload...
2015-08-18T19:03:55.468 INFO:teuthology.run_tasks:Running task internal.sudo...
2015-08-18T19:03:55.468 INFO:teuthology.task.internal:Configuring sudo...
2015-08-18T19:03:55.469 INFO:teuthology.orchestra.run.target170122:Running: "sudo sed -i.orig.teuthology -e 's/^\\([^#]*\\) \\(requiretty\\)/\\1 !\\2/g' -e 's/^\\([^#]*\\) !\\(visiblepw\\)/\\1 \\2/g' /etc/sudoers"
2015-08-18T19:03:55.539 INFO:teuthology.orchestra.run.target170123:Running: "sudo sed -i.orig.teuthology -e 's/^\\([^#]*\\) \\(requiretty\\)/\\1 !\\2/g' -e 's/^\\([^#]*\\) !\\(visiblepw\\)/\\1 \\2/g' /etc/sudoers"
2015-08-18T19:03:55.565 INFO:teuthology.run_tasks:Running task internal.syslog...
2015-08-18T19:03:55.566 INFO:teuthology.task.internal:Starting syslog monitoring...
2015-08-18T19:03:55.566 INFO:teuthology.orchestra.run.target170122:Running: 'mkdir -p -m0755 -- /home/ubuntu/cephtest/archive/syslog'
2015-08-18T19:03:55.637 INFO:teuthology.orchestra.run.target170123:Running: 'mkdir -p -m0755 -- /home/ubuntu/cephtest/archive/syslog'
2015-08-18T19:03:55.658 INFO:teuthology.orchestra.run.target170123:Running: 'touch /home/ubuntu/cephtest/archive/syslog/kern.log'
2015-08-18T19:03:55.741 INFO:teuthology.orchestra.run.target170123:Running: 'sudo chcon system_u:object_r:var_log_t:s0 /home/ubuntu/cephtest/archive/syslog/kern.log'
2015-08-18T19:03:55.835 INFO:teuthology.orchestra.run.target170123:Running: 'touch /home/ubuntu/cephtest/archive/syslog/misc.log'
2015-08-18T19:03:55.917 INFO:teuthology.orchestra.run.target170123:Running: 'sudo chcon system_u:object_r:var_log_t:s0 /home/ubuntu/cephtest/archive/syslog/misc.log'
2015-08-18T19:03:56.007 INFO:teuthology.orchestra.run.target170123:Running: 'sudo python -c \'import shutil, sys; shutil.copyfileobj(sys.stdin, file(sys.argv[1], "wb"))\' /etc/rsyslog.d/80-cephtest.conf'
2015-08-18T19:03:56.122 INFO:teuthology.orchestra.run.target170122:Running: 'touch /home/ubuntu/cephtest/archive/syslog/kern.log'
2015-08-18T19:03:56.138 INFO:teuthology.orchestra.run.target170122:Running: 'sudo chcon system_u:object_r:var_log_t:s0 /home/ubuntu/cephtest/archive/syslog/kern.log'
2015-08-18T19:03:56.233 INFO:teuthology.orchestra.run.target170122:Running: 'touch /home/ubuntu/cephtest/archive/syslog/misc.log'
2015-08-18T19:03:56.323 INFO:teuthology.orchestra.run.target170122:Running: 'sudo chcon system_u:object_r:var_log_t:s0 /home/ubuntu/cephtest/archive/syslog/misc.log'
2015-08-18T19:03:56.415 INFO:teuthology.orchestra.run.target170122:Running: 'sudo python -c \'import shutil, sys; shutil.copyfileobj(sys.stdin, file(sys.argv[1], "wb"))\' /etc/rsyslog.d/80-cephtest.conf'
2015-08-18T19:03:56.532 INFO:teuthology.orchestra.run.target170122:Running: 'sudo service rsyslog restart'
2015-08-18T19:03:56.602 INFO:teuthology.orchestra.run.target170123:Running: 'sudo service rsyslog restart'
2015-08-18T19:03:56.634 INFO:teuthology.orchestra.run.target170122.stderr:Redirecting to /bin/systemctl restart rsyslog.service
2015-08-18T19:03:56.642 INFO:teuthology.orchestra.run.target170123.stderr:Redirecting to /bin/systemctl restart rsyslog.service
2015-08-18T19:03:56.668 INFO:teuthology.run_tasks:Running task internal.timer...
2015-08-18T19:03:56.668 INFO:teuthology.task.internal:Starting timer...
2015-08-18T19:03:56.668 INFO:teuthology.run_tasks:Running task selinux...
2015-08-18T19:03:56.696 INFO:teuthology.task.selinux:Excluding target170123: VMs are not yet supported
2015-08-18T19:03:56.714 INFO:teuthology.task.selinux:Excluding target170122: VMs are not yet supported
2015-08-18T19:03:56.715 DEBUG:teuthology.task.selinux:Getting current SELinux state
2015-08-18T19:03:56.715 DEBUG:teuthology.task.selinux:Existing SELinux modes: {}
2015-08-18T19:03:56.715 INFO:teuthology.task.selinux:Putting SELinux into permissive mode
2015-08-18T19:03:56.715 INFO:teuthology.run_tasks:Running task ansible.cephlab...
2015-08-18T19:03:56.715 INFO:teuthology.repo_utils:Fetching from upstream into /home/ubuntu/src/ceph-cm-ansible_master
2015-08-18T19:03:57.365 INFO:teuthology.repo_utils:Resetting repo at /home/ubuntu/src/ceph-cm-ansible_master to branch master
2015-08-18T19:03:57.374 INFO:teuthology.task.ansible:Playbook: [{'include': 'ansible_managed.yml'}, {'include': 'teuthology.yml'}, {'include': 'testnodes.yml'}, {'include': 'cobbler.yml'}]
2015-08-18T19:03:57.374 DEBUG:teuthology.task.ansible:Running ansible-playbook -v --extra-vars '{"ansible_ssh_user": "ubuntu"}' -i /etc/ansible/hosts --limit target170123.teuthology,target170122.teuthology /home/ubuntu/src/ceph-cm-ansible_master/cephlab.yml
2015-08-18T19:04:02.106 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:02.108 INFO:teuthology.task.ansible.out:PLAY [all] ********************************************************************

2015-08-18T19:04:02.109 INFO:teuthology.task.ansible.out:
GATHERING FACTS ***************************************************************

2015-08-18T19:04:05.035 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology]

2015-08-18T19:04:05.044 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology]
2015-08-18T19:04:05.046 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.059 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.060 INFO:teuthology.task.ansible.out:TASK: [ansible-managed | Create the sudo group.] ******************************

2015-08-18T19:04:05.244 INFO:teuthology.task.ansible.out:changed: [target170122.teuthology] => {"changed": true, "gid": 1001, "name": "sudo", "state": "present", "system": false}
2015-08-18T19:04:05.248 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.383 INFO:teuthology.task.ansible.out:changed: [target170123.teuthology] => {"changed": true, "gid": 1001, "name": "sudo", "state": "present", "system": false}
2015-08-18T19:04:05.385 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.395 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.397 INFO:teuthology.task.ansible.out:TASK: [ansible-managed | Create the ansible user.] ****************************

2015-08-18T19:04:05.445 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:05.449 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.452 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:05.453 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.461 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.462 INFO:teuthology.task.ansible.out:TASK: [ansible-managed | Delete the ansible users password.] ******************

2015-08-18T19:04:05.511 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:05.513 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.514 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]

2015-08-18T19:04:05.522 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.523 INFO:teuthology.task.ansible.out:TASK: [ansible-managed | Ensure includedir is present in sudoers.] ************

2015-08-18T19:04:05.781 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology] => {"backup": "", "changed": false, "msg": ""}
2015-08-18T19:04:05.783 INFO:teuthology.task.ansible.out:
ok: [target170123.teuthology] => {"backup": "", "changed": false, "msg": ""}

2015-08-18T19:04:05.796 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:05.797 INFO:teuthology.task.ansible.out:TASK: [ansible-managed | Create the cephlab_sudo sudoers.d file.] *************

2015-08-18T19:04:07.381 INFO:teuthology.task.ansible.out:changed: [target170122.teuthology] => {"changed": true, "checksum": "158278c249946d31eee51afb618375e5b7e315ce", "dest": "/etc/sudoers.d/cephlab_sudo", "gid": 0, "group": "root", "md5sum": "823b295a0b9fadad46ebd09bcec7dcdc", "mode": "0440", "owner": "root", "secontext": "system_u:object_r:etc_t:s0", "size": 255, "src": "/home/ubuntu/.ansible/tmp/ansible-tmp-1439924645.84-152126507970616/source", "state": "file", "uid": 0}
2015-08-18T19:04:07.383 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:07.493 INFO:teuthology.task.ansible.out:changed: [target170123.teuthology] => {"changed": true, "checksum": "158278c249946d31eee51afb618375e5b7e315ce", "dest": "/etc/sudoers.d/cephlab_sudo", "gid": 0, "group": "root", "md5sum": "823b295a0b9fadad46ebd09bcec7dcdc", "mode": "0440", "owner": "root", "secontext": "system_u:object_r:etc_t:s0", "size": 255, "src": "/home/ubuntu/.ansible/tmp/ansible-tmp-1439924645.97-14690004147991/source", "state": "file", "uid": 0}
2015-08-18T19:04:07.494 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:07.505 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:07.507 INFO:teuthology.task.ansible.out:TASK: [ansible-managed | Add authorized keys for the ansible user.] ***********

2015-08-18T19:04:07.560 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology] => (item=ansible_user_ssh_keys)
2015-08-18T19:04:07.561 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:07.563 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology] => (item=ansible_user_ssh_keys)
2015-08-18T19:04:07.565 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:07.572 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:07.574 INFO:teuthology.task.ansible.out:PLAY [teuthology] *************************************************************

2015-08-18T19:04:07.580 INFO:teuthology.task.ansible.out:skipping: no hosts matched
2015-08-18T19:04:07.581 INFO:teuthology.task.ansible.out:

PLAY [testnodes] **************************************************************

2015-08-18T19:04:08.161 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.162 INFO:teuthology.task.ansible.out:GATHERING FACTS ***************************************************************

2015-08-18T19:04:08.602 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology]
2015-08-18T19:04:08.604 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.608 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology]
2015-08-18T19:04:08.610 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.619 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.620 INFO:teuthology.task.ansible.out:TASK: [users | Filter the managed_users list] *********************************

2015-08-18T19:04:08.661 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:08.665 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.666 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:08.667 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.674 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.675 INFO:teuthology.task.ansible.out:TASK: [users | Filter the managed_admin_users list] ***************************

2015-08-18T19:04:08.717 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:08.718 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.721 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:08.722 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.729 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.730 INFO:teuthology.task.ansible.out:TASK: [users | Create all admin users with sudo access.] **********************

2015-08-18T19:04:08.775 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:08.776 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.778 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]

2015-08-18T19:04:08.785 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.786 INFO:teuthology.task.ansible.out:TASK: [users | Create all users without sudo access.] *************************

2015-08-18T19:04:08.829 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:08.830 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.831 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]

2015-08-18T19:04:08.838 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.839 INFO:teuthology.task.ansible.out:TASK: [users | Update authorized_keys for each user.] *************************

2015-08-18T19:04:08.884 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:08.885 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.886 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]

2015-08-18T19:04:08.893 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.895 INFO:teuthology.task.ansible.out:TASK: [users | Filter the revoked_users list] *********************************

2015-08-18T19:04:08.936 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:08.937 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.940 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:08.942 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.949 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.950 INFO:teuthology.task.ansible.out:TASK: [users | Remove revoked users] ******************************************

2015-08-18T19:04:08.992 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:08.993 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:08.996 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:08.997 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.004 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.005 INFO:teuthology.task.ansible.out:TASK: [common | Log the OS name, version and release] *************************

2015-08-18T19:04:09.056 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology] => {
2015-08-18T19:04:09.058 INFO:teuthology.task.ansible.out:
"msg": "Host target170123.teuthology is running RedHat 7.1.1503 (Core)"
}
ok: [target170122.teuthology] => {
"msg": "Host target170122.teuthology is running RedHat 7.1.1503 (Core)"
}

2015-08-18T19:04:09.066 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.067 INFO:teuthology.task.ansible.out:TASK: [common | Including major version specific variables.] ******************

2015-08-18T19:04:09.119 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology] => (item=/home/ubuntu/src/ceph-cm-ansible_master/roles/common/vars/redhat_7.yml) => {"ansible_facts": {"rhsm_repos": ["rhel-7-server-rpms", "rhel-7-server-optional-rpms", "rhel-7-server-extras-rpms"]}, "item": "/home/ubuntu/src/ceph-cm-ansible_master/roles/common/vars/redhat_7.yml"}
2015-08-18T19:04:09.121 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.122 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology] => (item=/home/ubuntu/src/ceph-cm-ansible_master/roles/common/vars/redhat_7.yml) => {"ansible_facts": {"rhsm_repos": ["rhel-7-server-rpms", "rhel-7-server-optional-rpms", "rhel-7-server-extras-rpms"]}, "item": "/home/ubuntu/src/ceph-cm-ansible_master/roles/common/vars/redhat_7.yml"}

2015-08-18T19:04:09.129 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.130 INFO:teuthology.task.ansible.out:TASK: [common | Set entitlements_path] ****************************************

2015-08-18T19:04:09.182 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology] => {"ansible_facts": {"entitlements_path": "/etc/ansible/secrets/entitlements.yml"}}
2015-08-18T19:04:09.184 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.185 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology] => {"ansible_facts": {"entitlements_path": "/etc/ansible/secrets/entitlements.yml"}}

2015-08-18T19:04:09.192 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.193 INFO:teuthology.task.ansible.out:TASK: [common | Include Red Hat encrypted variables.] *************************

2015-08-18T19:04:09.247 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology] => {"censored": "results hidden due to no_log parameter"}
2015-08-18T19:04:09.249 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.250 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology] => {"censored": "results hidden due to no_log parameter"}

2015-08-18T19:04:09.256 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.258 INFO:teuthology.task.ansible.out:TASK: [common | Set have_entitlements] ****************************************

2015-08-18T19:04:09.308 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology] => {"ansible_facts": {"have_entitlements": "False"}}
2015-08-18T19:04:09.309 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.311 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology] => {"ansible_facts": {"have_entitlements": "False"}}
2015-08-18T19:04:09.312 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.318 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.320 INFO:teuthology.task.ansible.out:TASK: [common | Determine if node is registered with subscription-manager.] ***

2015-08-18T19:04:09.619 INFO:teuthology.task.ansible.out:failed: [target170122.teuthology] => {"censored": "results hidden due to no_log parameter", "changed": false, "failed": true, "rc": 2}
2015-08-18T19:04:09.620 INFO:teuthology.task.ansible.out:
...ignoring

2015-08-18T19:04:09.622 INFO:teuthology.task.ansible.out:failed: [target170123.teuthology] => {"censored": "results hidden due to no_log parameter", "changed": false, "failed": true, "rc": 2}
2015-08-18T19:04:09.624 INFO:teuthology.task.ansible.out:
...ignoring

2015-08-18T19:04:09.635 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.636 INFO:teuthology.task.ansible.out:TASK: [common | Set rhsm_registered] ******************************************

2015-08-18T19:04:09.691 INFO:teuthology.task.ansible.out:ok: [target170122.teuthology] => {"ansible_facts": {"rhsm_registered": "False"}}
2015-08-18T19:04:09.693 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.695 INFO:teuthology.task.ansible.out:ok: [target170123.teuthology] => {"ansible_facts": {"rhsm_registered": "False"}}
2015-08-18T19:04:09.697 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.703 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.704 INFO:teuthology.task.ansible.out:TASK: [common | Register with subscription-manager.] **************************

2015-08-18T19:04:09.750 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology] => (item={'skipped': True, 'censored': 'results hidden due to no_log parameter', 'changed': False})
2015-08-18T19:04:09.754 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.756 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology] => (item={'skipped': True, 'censored': 'results hidden due to no_log parameter', 'changed': False})
2015-08-18T19:04:09.757 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.765 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.766 INFO:teuthology.task.ansible.out:TASK: [common | Get list of enabled repos] ************************************

2015-08-18T19:04:09.812 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:09.816 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.817 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]

2015-08-18T19:04:09.825 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.826 INFO:teuthology.task.ansible.out:TASK: [common | Store list of enabled repos] **********************************

2015-08-18T19:04:09.873 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:09.874 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.877 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:09.878 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.885 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.887 INFO:teuthology.task.ansible.out:TASK: [common | Set replace_repos if rhsm_repos differs from repo_list] *******

2015-08-18T19:04:09.933 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]
2015-08-18T19:04:09.934 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.936 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]

2015-08-18T19:04:09.944 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.945 INFO:teuthology.task.ansible.out:TASK: [common | Set replace_repos if newly-subscribed] ************************

2015-08-18T19:04:09.994 INFO:teuthology.task.ansible.out:skipping: [target170122.teuthology]
2015-08-18T19:04:09.995 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:09.996 INFO:teuthology.task.ansible.out:skipping: [target170123.teuthology]

2015-08-18T19:04:10.004 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:10.006 INFO:teuthology.task.ansible.out:TASK: [common | Disable all rhsm repos] ***************************************

2015-08-18T19:04:10.052 INFO:teuthology.task.ansible.out:fatal: [target170122.teuthology] => error while evaluating conditional: replace_repos
2015-08-18T19:04:10.053 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:10.055 INFO:teuthology.task.ansible.out:fatal: [target170123.teuthology] => error while evaluating conditional: replace_repos
2015-08-18T19:04:10.057 INFO:teuthology.task.ansible.out:

2015-08-18T19:04:10.066 INFO:teuthology.task.ansible.out:
2015-08-18T19:04:10.068 INFO:teuthology.task.ansible.out:
FATAL: all hosts have already failed -- aborting

PLAY RECAP ********************************************************************
to retry, use: --limit @/home/ubuntu/cephlab.retry

target170122.teuthology : ok=13 changed=2 unreachable=1 failed=0
target170123.teuthology : ok=13 changed=2 unreachable=1 failed=0


2015-08-18T19:04:10.191 ERROR:teuthology.run_tasks:Saw exception from tasks.
Traceback (most recent call last):
File "/home/ubuntu/teuthology/teuthology/run_tasks.py", line 56, in run_tasks
manager.__enter__()
File "/home/ubuntu/teuthology/teuthology/task/__init__.py", line 121, in __enter__
self.begin()
File "/home/ubuntu/teuthology/teuthology/task/ansible.py", line 230, in begin
self.execute_playbook()
File "/home/ubuntu/teuthology/teuthology/task/ansible.py", line 255, in execute_playbook
self._handle_failure(command, status)
File "/home/ubuntu/teuthology/teuthology/task/ansible.py", line 266, in _handle_failure
failures = yaml.safe_load(log)
File "/home/ubuntu/teuthology/virtualenv/local/lib/python2.7/site-packages/yaml/__init__.py", line 93, in safe_load
return load(stream, SafeLoader)
File "/home/ubuntu/teuthology/virtualenv/local/lib/python2.7/site-packages/yaml/__init__.py", line 71, in load
return loader.get_single_data()
File "/home/ubuntu/teuthology/virtualenv/local/lib/python2.7/site-packages/yaml/constructor.py", line 37, in get_single_data
node = self.get_single_node()
File "/home/ubuntu/teuthology/virtualenv/local/lib/python2.7/site-packages/yaml/composer.py", line 39, in get_single_node
if not self.check_event(StreamEndEvent):
File "/home/ubuntu/teuthology/virtualenv/local/lib/python2.7/site-packages/yaml/parser.py", line 98, in check_event
self.current_event = self.state()
File "/home/ubuntu/teuthology/virtualenv/local/lib/python2.7/site-packages/yaml/parser.py", line 174, in parse_document_start
self.peek_token().start_mark)
ParserError: expected '<document start>', but found '{'
in "/tmp/teuth_ansible_failures_hp9sRK", line 3, column 1
2015-08-18T19:04:10.193 DEBUG:teuthology.run_tasks:Unwinding manager ansible.cephlab
2015-08-18T19:04:10.193 INFO:teuthology.task.ansible:Skipping ansible cleanup...
2015-08-18T19:04:10.193 DEBUG:teuthology.run_tasks:Unwinding manager selinux
2015-08-18T19:04:10.194 DEBUG:teuthology.run_tasks:Unwinding manager internal.timer
2015-08-18T19:04:10.194 INFO:teuthology.task.internal:Duration was 13.525760 seconds
2015-08-18T19:04:10.194 DEBUG:teuthology.run_tasks:Unwinding manager internal.syslog
2015-08-18T19:04:10.195 INFO:teuthology.task.internal:Shutting down syslog monitoring...
2015-08-18T19:04:10.195 INFO:teuthology.orchestra.run.target170122:Running: 'sudo rm -f -- /etc/rsyslog.d/80-cephtest.conf && sudo service rsyslog restart'
2015-08-18T19:04:10.201 INFO:teuthology.orchestra.run.target170123:Running: 'sudo rm -f -- /etc/rsyslog.d/80-cephtest.conf && sudo service rsyslog restart'
2015-08-18T19:04:10.246 INFO:teuthology.orchestra.run.target170122.stderr:Redirecting to /bin/systemctl restart rsyslog.service
2015-08-18T19:04:10.249 INFO:teuthology.orchestra.run.target170123.stderr:Redirecting to /bin/systemctl restart rsyslog.service
2015-08-18T19:04:10.282 INFO:teuthology.task.internal:Checking logs for errors...
2015-08-18T19:04:10.283 DEBUG:teuthology.task.internal:Checking ubuntu@target170123.teuthology
2015-08-18T19:04:10.283 INFO:teuthology.orchestra.run.target170123:Running: "egrep --binary-files=text '\\bBUG\\b|\\bINFO\\b|\\bDEADLOCK\\b' /home/ubuntu/cephtest/archive/syslog/*.log | grep -v 'task .* blocked for more than .* seconds' | grep -v 'lockdep is turned off' | grep -v 'trying to register non-static key' | grep -v 'DEBUG: fsize' | grep -v CRON | grep -v 'BUG: bad unlock balance detected' | grep -v 'inconsistent lock state' | grep -v '*** DEADLOCK ***' | grep -v 'INFO: possible irq lock inversion dependency detected' | grep -v 'INFO: NMI handler (perf_event_nmi_handler) took too long to run' | grep -v 'INFO: recovery required on readonly' | head -n 1"
2015-08-18T19:04:10.320 DEBUG:teuthology.task.internal:Checking ubuntu@target170122.teuthology
2015-08-18T19:04:10.321 INFO:teuthology.orchestra.run.target170122:Running: "egrep --binary-files=text '\\bBUG\\b|\\bINFO\\b|\\bDEADLOCK\\b' /home/ubuntu/cephtest/archive/syslog/*.log | grep -v 'task .* blocked for more than .* seconds' | grep -v 'lockdep is turned off' | grep -v 'trying to register non-static key' | grep -v 'DEBUG: fsize' | grep -v CRON | grep -v 'BUG: bad unlock balance detected' | grep -v 'inconsistent lock state' | grep -v '*** DEADLOCK ***' | grep -v 'INFO: possible irq lock inversion dependency detected' | grep -v 'INFO: NMI handler (perf_event_nmi_handler) took too long to run' | grep -v 'INFO: recovery required on readonly' | head -n 1"
2015-08-18T19:04:10.354 INFO:teuthology.task.internal:Compressing syslogs...
2015-08-18T19:04:10.354 INFO:teuthology.orchestra.run.target170122:Running: "find /home/ubuntu/cephtest/archive/syslog -name '*.log' -print0 | sudo xargs -0 --no-run-if-empty -- gzip --"
2015-08-18T19:04:10.423 INFO:teuthology.orchestra.run.target170123:Running: "find /home/ubuntu/cephtest/archive/syslog -name '*.log' -print0 | sudo xargs -0 --no-run-if-empty -- gzip --"
2015-08-18T19:04:10.454 DEBUG:teuthology.run_tasks:Unwinding manager internal.sudo
2015-08-18T19:04:10.455 INFO:teuthology.task.internal:Restoring /etc/sudoers...
2015-08-18T19:04:10.455 INFO:teuthology.orchestra.run.target170122:Running: 'sudo mv -f /etc/sudoers.orig.teuthology /etc/sudoers'
2015-08-18T19:04:10.552 INFO:teuthology.orchestra.run.target170123:Running: 'sudo mv -f /etc/sudoers.orig.teuthology /etc/sudoers'
2015-08-18T19:04:10.579 DEBUG:teuthology.run_tasks:Unwinding manager internal.archive_upload
2015-08-18T19:04:10.579 INFO:teuthology.task.internal:Not uploading archives.
2015-08-18T19:04:10.580 DEBUG:teuthology.run_tasks:Unwinding manager internal.coredump
2015-08-18T19:04:10.580 INFO:teuthology.orchestra.run.target170122:Running: 'sudo sysctl -w kernel.core_pattern=core && rmdir --ignore-fail-on-non-empty -- /home/ubuntu/cephtest/archive/coredump'
2015-08-18T19:04:10.600 INFO:teuthology.orchestra.run.target170123:Running: 'sudo sysctl -w kernel.core_pattern=core && rmdir --ignore-fail-on-non-empty -- /home/ubuntu/cephtest/archive/coredump'
2015-08-18T19:04:10.617 INFO:teuthology.orchestra.run.target170122.stdout:kernel.core_pattern = core
2015-08-18T19:04:10.643 INFO:teuthology.orchestra.run.target170123.stdout:kernel.core_pattern = core
2015-08-18T19:04:10.647 INFO:teuthology.orchestra.run.target170123:Running: "if test '!' -e /home/ubuntu/cephtest/archive/coredump ; then echo OK ; fi"
2015-08-18T19:04:10.727 INFO:teuthology.orchestra.run.target170122:Running: "if test '!' -e /home/ubuntu/cephtest/archive/coredump ; then echo OK ; fi"
2015-08-18T19:04:10.743 DEBUG:teuthology.run_tasks:Unwinding manager internal.archive
2015-08-18T19:04:10.743 INFO:teuthology.task.internal:Transferring archived files...
2015-08-18T19:04:10.744 DEBUG:teuthology.misc:Transferring archived files from target170123:/home/ubuntu/cephtest/archive to /usr/share/nginx/html/ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack/22/remote/target170123
2015-08-18T19:04:10.744 INFO:teuthology.orchestra.run.target170123:Running: "python -c 'import os; import tempfile; import sys;(fd,fname) = tempfile.mkstemp();os.close(fd);sys.stdout.write(fname.rstrip());sys.stdout.flush()'"
2015-08-18T19:04:10.816 INFO:teuthology.orchestra.run.target170123:Running: 'sudo tar cz -f /tmp/tmp9igDwU -C /home/ubuntu/cephtest/archive -- .'
2015-08-18T19:04:10.919 INFO:teuthology.orchestra.run.target170123:Running: 'sudo chmod 0666 /tmp/tmp9igDwU'
2015-08-18T19:04:11.104 INFO:teuthology.orchestra.run.target170123:Running: 'rm -fr /tmp/tmp9igDwU'
2015-08-18T19:04:11.125 DEBUG:teuthology.misc:Transferring archived files from target170122:/home/ubuntu/cephtest/archive to /usr/share/nginx/html/ubuntu-2015-08-18_19:00:05-ceph-deploy-wip-11881-multipath---basic-openstack/22/remote/target170122
2015-08-18T19:04:11.126 INFO:teuthology.orchestra.run.target170122:Running: "python -c 'import os; import tempfile; import sys;(fd,fname) = tempfile.mkstemp();os.close(fd);sys.stdout.write(fname.rstrip());sys.stdout.flush()'"
2015-08-18T19:04:11.164 INFO:teuthology.orchestra.run.target170122:Running: 'sudo tar cz -f /tmp/tmpIUkEtn -C /home/ubuntu/cephtest/archive -- .'
2015-08-18T19:04:11.266 INFO:teuthology.orchestra.run.target170122:Running: 'sudo chmod 0666 /tmp/tmpIUkEtn'
2015-08-18T19:04:11.451 INFO:teuthology.orchestra.run.target170122:Running: 'rm -fr /tmp/tmpIUkEtn'
2015-08-18T19:04:11.468 INFO:teuthology.task.internal:Removing archive directory...
2015-08-18T19:04:11.468 INFO:teuthology.orchestra.run.target170122:Running: 'rm -rf -- /home/ubuntu/cephtest/archive'
2015-08-18T19:04:11.538 INFO:teuthology.orchestra.run.target170123:Running: 'rm -rf -- /home/ubuntu/cephtest/archive'
2015-08-18T19:04:12.250 DEBUG:teuthology.run_tasks:Unwinding manager internal.base
2015-08-18T19:04:12.250 INFO:teuthology.task.internal:Tidying up after the test...
2015-08-18T19:04:12.250 INFO:teuthology.orchestra.run.target170122:Running: 'rmdir -- /home/ubuntu/cephtest'
2015-08-18T19:04:12.257 INFO:teuthology.orchestra.run.target170123:Running: 'rmdir -- /home/ubuntu/cephtest'
2015-08-18T19:04:12.275 DEBUG:teuthology.run_tasks:Unwinding manager internal.lock_machines
2015-08-18T19:04:12.276 DEBUG:teuthology.run_tasks:Exception was not quenched, exiting: ParserError: expected '<document start>', but found '{'
in "/tmp/teuth_ansible_failures_hp9sRK", line 3, column 1
2015-08-18T19:04:12.277 INFO:teuthology.nuke:Checking targets against current locks
2015-08-18T19:04:12.857 DEBUG:teuthology.provision:ProvisionOpenStack: {'machine': {'disk': 20, 'ram': 8000, 'cpus': 1}, 'subnet': '149.202.160.0/19', 'volumes': {'count': 0, 'size': 1}, 'user-data': 'teuthology/openstack/openstack-{os_type}-{os_version}-user-data.txt', 'ip': '149.202.169.83', 'flavor-select-regexp': '^(vps|eg)-', 'nameserver': '149.202.169.83'}
2015-08-18T19:04:12.858 DEBUG:teuthology.provision:ProvisionOpenStack:destroy target170122
2015-08-18T19:04:12.858 DEBUG:teuthology.misc:openstack server list -f json
2015-08-18T19:04:14.473 DEBUG:teuthology.misc:openstack server list -f json output [{"ID": "d6613710-423a-4994-93dc-88f0058ee505", "Name": "target170123", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.123"}, {"ID": "26e2cecf-4b16-4689-9cd6-1a1683bd606f", "Name": "target170122", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.122"}, {"ID": "525337d6-3dde-455e-8057-c50c25fbe43b", "Name": "target170108", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.108"}, {"ID": "67c9495c-b744-46bd-805a-d15c45f9852c", "Name": "target170107", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.107"}, {"ID": "36d7f91a-b42d-4576-8189-4c7b44f1b8b7", "Name": "target170104", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.104"}, {"ID": "24373280-994a-4f5e-9778-870d65fc4216", "Name": "target170103", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.103"}, {"ID": "3dd36b73-f732-4629-8d40-3e69e2b56795", "Name": "target170105", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.105"}, {"ID": "1512c8a5-61b9-4101-a104-4e1a66575af6", "Name": "target170106", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.106"}, {"ID": "7b20e6c7-6bfc-4c7c-b400-29f753b9e35c", "Name": "target170101", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.101"}, {"ID": "166db435-28c2-4159-aec4-86aba5db2834", "Name": "target170102", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.102"}, {"ID": "e15522ff-2404-4640-bf69-b5e5674900e1", "Name": "teuthology", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.169.83"}, {"ID": "018bc993-6944-4428-a057-6c2f3e472a33", "Name": "other", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.161.79"}]

2015-08-18T19:04:14.474 DEBUG:teuthology.misc:openstack server show -f json target170122
2015-08-18T19:04:16.605 DEBUG:teuthology.misc:openstack server show -f json target170122 output [{"Field": "OS-DCF:diskConfig", "Value": "MANUAL"}, {"Field": "OS-EXT-AZ:availability_zone", "Value": "nova"}, {"Field": "OS-EXT-STS:power_state", "Value": 1}, {"Field": "OS-EXT-STS:task_state", "Value": null}, {"Field": "OS-EXT-STS:vm_state", "Value": "active"}, {"Field": "OS-SRV-USG:launched_at", "Value": "2015-08-18T19:01:30.000000"}, {"Field": "OS-SRV-USG:terminated_at", "Value": null}, {"Field": "accessIPv4", "Value": ""}, {"Field": "accessIPv6", "Value": ""}, {"Field": "addresses", "Value": "Ext-Net=149.202.170.122"}, {"Field": "config_drive", "Value": ""}, {"Field": "created", "Value": "2015-08-18T19:00:15Z"}, {"Field": "flavor", "Value": "vps-ssd-1 (98c1e679-5f2c-4069-b4da-4a4f7179b758)"}, {"Field": "hostId", "Value": "643dffa5fd86216e17116ac0b2b145e2410835ccdba3e2f75fcc9cd5"}, {"Field": "id", "Value": "26e2cecf-4b16-4689-9cd6-1a1683bd606f"}, {"Field": "image", "Value": "teuthology-centos-7.0 (94967743-087d-44d3-a9bc-1bfe9481127b)"}, {"Field": "key_name", "Value": "teuthology"}, {"Field": "name", "Value": "target170122"}, {"Field": "os-extended-volumes:volumes_attached", "Value": [{"id": "bbe65cd7-0530-4929-ab86-b0236cb6ef6b"}, {"id": "7f6246dd-89fb-4239-b608-a766e4af0de2"}, {"id": "b15f45da-dd66-4ddd-a8dd-e127737cee33"}]}, {"Field": "progress", "Value": 0}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"Field": "security_groups", "Value": [{"name": "teuthology"}]}, {"Field": "status", "Value": "ACTIVE"}, {"Field": "updated", "Value": "2015-08-18T19:03:18Z"}, {"Field": "user_id", "Value": "3a075820e5d24fda96cd340b87fd94e9"}]

2015-08-18T19:04:16.606 DEBUG:teuthology.misc:openstack server delete --wait target170122
2015-08-18T19:04:23.576 DEBUG:teuthology.misc:openstack server delete --wait target170122 output

2015-08-18T19:04:23.576 DEBUG:teuthology.misc:openstack volume delete bbe65cd7-0530-4929-ab86-b0236cb6ef6b
2015-08-18T19:04:24.770 DEBUG:teuthology.misc:openstack volume delete bbe65cd7-0530-4929-ab86-b0236cb6ef6b output
2015-08-18T19:04:24.771 DEBUG:teuthology.misc:openstack volume delete 7f6246dd-89fb-4239-b608-a766e4af0de2
2015-08-18T19:04:25.918 DEBUG:teuthology.misc:openstack volume delete 7f6246dd-89fb-4239-b608-a766e4af0de2 output
2015-08-18T19:04:25.919 DEBUG:teuthology.misc:openstack volume delete b15f45da-dd66-4ddd-a8dd-e127737cee33
2015-08-18T19:04:27.288 DEBUG:teuthology.misc:openstack volume delete b15f45da-dd66-4ddd-a8dd-e127737cee33 output
2015-08-18T19:04:27.292 DEBUG:teuthology.provision:ProvisionOpenStack: {'machine': {'disk': 20, 'ram': 8000, 'cpus': 1}, 'subnet': '149.202.160.0/19', 'volumes': {'count': 0, 'size': 1}, 'user-data': 'teuthology/openstack/openstack-{os_type}-{os_version}-user-data.txt', 'ip': '149.202.169.83', 'flavor-select-regexp': '^(vps|eg)-', 'nameserver': '149.202.169.83'}
2015-08-18T19:04:27.292 DEBUG:teuthology.provision:ProvisionOpenStack:destroy target170123
2015-08-18T19:04:27.293 DEBUG:teuthology.misc:openstack server list -f json
2015-08-18T19:04:28.645 DEBUG:teuthology.misc:openstack server list -f json output [{"ID": "d6613710-423a-4994-93dc-88f0058ee505", "Name": "target170123", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.123"}, {"ID": "525337d6-3dde-455e-8057-c50c25fbe43b", "Name": "target170108", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.108"}, {"ID": "67c9495c-b744-46bd-805a-d15c45f9852c", "Name": "target170107", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.107"}, {"ID": "36d7f91a-b42d-4576-8189-4c7b44f1b8b7", "Name": "target170104", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.104"}, {"ID": "24373280-994a-4f5e-9778-870d65fc4216", "Name": "target170103", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.103"}, {"ID": "3dd36b73-f732-4629-8d40-3e69e2b56795", "Name": "target170105", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.105"}, {"ID": "1512c8a5-61b9-4101-a104-4e1a66575af6", "Name": "target170106", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.106"}, {"ID": "7b20e6c7-6bfc-4c7c-b400-29f753b9e35c", "Name": "target170101", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.101"}, {"ID": "166db435-28c2-4159-aec4-86aba5db2834", "Name": "target170102", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.170.102"}, {"ID": "e15522ff-2404-4640-bf69-b5e5674900e1", "Name": "teuthology", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.169.83"}, {"ID": "018bc993-6944-4428-a057-6c2f3e472a33", "Name": "other", "Status": "ACTIVE", "Networks": "Ext-Net=149.202.161.79"}]

2015-08-18T19:04:28.645 DEBUG:teuthology.misc:openstack server show -f json target170123
2015-08-18T19:04:30.616 DEBUG:teuthology.misc:openstack server show -f json target170123 output [{"Field": "OS-DCF:diskConfig", "Value": "MANUAL"}, {"Field": "OS-EXT-AZ:availability_zone", "Value": "nova"}, {"Field": "OS-EXT-STS:power_state", "Value": 1}, {"Field": "OS-EXT-STS:task_state", "Value": null}, {"Field": "OS-EXT-STS:vm_state", "Value": "active"}, {"Field": "OS-SRV-USG:launched_at", "Value": "2015-08-18T19:01:30.000000"}, {"Field": "OS-SRV-USG:terminated_at", "Value": null}, {"Field": "accessIPv4", "Value": ""}, {"Field": "accessIPv6", "Value": ""}, {"Field": "addresses", "Value": "Ext-Net=149.202.170.123"}, {"Field": "config_drive", "Value": ""}, {"Field": "created", "Value": "2015-08-18T19:00:15Z"}, {"Field": "flavor", "Value": "vps-ssd-1 (98c1e679-5f2c-4069-b4da-4a4f7179b758)"}, {"Field": "hostId", "Value": "643dffa5fd86216e17116ac0b2b145e2410835ccdba3e2f75fcc9cd5"}, {"Field": "id", "Value": "d6613710-423a-4994-93dc-88f0058ee505"}, {"Field": "image", "Value": "teuthology-centos-7.0 (94967743-087d-44d3-a9bc-1bfe9481127b)"}, {"Field": "key_name", "Value": "teuthology"}, {"Field": "name", "Value": "target170123"}, {"Field": "os-extended-volumes:volumes_attached", "Value": [{"id": "3bd7faab-8d4f-4096-bf68-5c4d867160e0"}, {"id": "1d720c05-7817-4be9-9d77-86578bb0855a"}, {"id": "e8432272-a4f8-46a1-979c-ecae56fbca89"}]}, {"Field": "progress", "Value": 0}, {"Field": "project_id", "Value": "62cf1be03cec403c8ed8e64df55732ea"}, {"Field": "properties", "Value": "ownedby='149.202.169.83', teuthology='13aabdf5663d60d735e873a24a924c25'"}, {"Field": "security_groups", "Value": [{"name": "teuthology"}]}, {"Field": "status", "Value": "ACTIVE"}, {"Field": "updated", "Value": "2015-08-18T19:01:39Z"}, {"Field": "user_id", "Value": "3a075820e5d24fda96cd340b87fd94e9"}]

2015-08-18T19:04:30.617 DEBUG:teuthology.misc:openstack server delete --wait target170123
2015-08-18T19:04:37.781 DEBUG:teuthology.misc:openstack server delete --wait target170123 output

2015-08-18T19:04:37.781 DEBUG:teuthology.misc:openstack volume delete 3bd7faab-8d4f-4096-bf68-5c4d867160e0
2015-08-18T19:04:39.138 DEBUG:teuthology.misc:openstack volume delete 3bd7faab-8d4f-4096-bf68-5c4d867160e0 output
2015-08-18T19:04:39.138 DEBUG:teuthology.misc:openstack volume delete 1d720c05-7817-4be9-9d77-86578bb0855a
2015-08-18T19:04:40.554 DEBUG:teuthology.misc:openstack volume delete 1d720c05-7817-4be9-9d77-86578bb0855a output
2015-08-18T19:04:40.554 DEBUG:teuthology.misc:openstack volume delete e8432272-a4f8-46a1-979c-ecae56fbca89
2015-08-18T19:04:41.825 DEBUG:teuthology.misc:openstack volume delete e8432272-a4f8-46a1-979c-ecae56fbca89 output
2015-08-18T19:04:41.854 INFO:teuthology.lock:unlocked target170122.teuthology
2015-08-18T19:04:41.872 INFO:teuthology.lock:unlocked target170123.teuthology
2015-08-18T19:04:41.882 INFO:teuthology.run:Summary data:
{description: 'ceph-deploy/basic/{ceph-deploy-overrides/disable_diff_journal_disk.yaml
config_options/cephdeploy_conf.yaml distros/centos_7.0.yaml tasks/ceph-deploy_hello_world.yaml}',
duration: 13.525759935379028, failure_reason: "expected '<document start>', but\
\ found '{'\n in \"/tmp/teuth_ansible_failures_hp9sRK\", line 3, column 1", owner: scheduled_ubuntu@teuthology,
status: fail, success: false}

2015-08-18T19:04:41.882 DEBUG:teuthology.report:Pushing job info to http://localhost:8080/
2015-08-18T19:04:41.918 INFO:teuthology.run:FAIL
(1-1/2)