TRACE: 1 22-22-23->0s=0:00:00.000245s status=OK step=show plc=plctest1_vplc20 force=False
TRACE: 1 22-22-23->1s=0:00:01.449695s status=OK step=plcvm_delete plc=plctest1_vplc20 force=False
TRACE: 1 22-22-24->0s=0:00:00.535500s status=OK step=plcvm_timestamp plc=plctest1_vplc20 force=False
TRACE: 1 22-22-25->29s=0:00:29.139338s status=OK step=plcvm_create plc=plctest1_vplc20 force=False
TRACE: 1 22-22-54->75s=0:01:15.268414s status=OK step=plc_install plc=plctest1_vplc20 force=False
TRACE: 1 22-24-09->0s=0:00:00.793789s status=OK step=plc_configure plc=plctest1_vplc20 force=False
TRACE: 1 22-24-10->20s=0:00:20.678912s status=OK step=plc_start plc=plctest1_vplc20 force=False
TRACE: 1 22-24-31->0s=0:00:00.534898s status=OK step=keys_fetch plc=plctest1_vplc20 force=False
TRACE: 1 22-24-31->0s=0:00:00.001535s status=OK step=keys_store plc=plctest1_vplc20 force=False
TRACE: 1 22-24-31->0s=0:00:00.017809s status=OK step=keys_clear_known_hosts plc=plctest1_vplc20 force=False
TRACE: 1 22-24-31->0s=0:00:00.339000s status=OK step=plcapi_urls plc=plctest1_vplc20 force=False
TRACE: 1 22-24-32->0s=0:00:00.310181s status=OK step=speed_up_slices plc=plctest1_vplc20 force=False
TRACE: 1 22-24-32->0s=0:00:00.021627s status=OK step=initscripts plc=plctest1_vplc20 force=False
TRACE: 1 22-24-32->0s=0:00:00.969038s status=OK step=sites plc=plctest1_vplc20 force=False
TRACE: 1 22-24-33->0s=0:00:00.144377s status=OK step=nodes plc=plctest1_vplc20 force=False
TRACE: 1 22-24-33->0s=0:00:00.577016s status=OK step=slices plc=plctest1_vplc20 force=False
TRACE: 1 22-24-34->0s=0:00:00.109744s status=OK step=nodegroups plc=plctest1_vplc20 force=False
TRACE: 1 22-24-34->0s=0:00:00.016198s status=OK step=leases plc=plctest1_vplc20 force=False
TRACE: 1 22-24-34->0s=0:00:00.063359s status=OK[I] step=check_vsys_defaults_ignore plc=plctest1_vplc20 force=False
TRACE: 1 22-24-34->0s=0:00:00.539561s status=OK step=qemu_kill_mine plc=plctest1_vplc20 force=False
TRACE: 1 22-24-34->0s=0:00:00.043467s status=OK step=nodestate_reinstall plc=plctest1_vplc20 force=False
TRACE: 1 22-24-34->0s=0:00:00.020881s status=OK step=qemu_local_init plc=plctest1_vplc20 force=False
TRACE: 1 22-24-35->7s=0:00:07.180233s status=OK step=bootcd plc=plctest1_vplc20 force=False
TRACE: 1 22-24-42->0s=0:00:00.049923s status=OK step=qemu_local_config plc=plctest1_vplc20 force=False
TRACE: 1 22-24-42->0s=0:00:00.273161s status=OK step=qemu_clean_mine plc=plctest1_vplc20 force=False
TRACE: 1 22-24-42->3s=0:00:03.851609s status=OK step=qemu_export plc=plctest1_vplc20 force=False
TRACE: 1 22-24-46->0s=0:00:00.691829s status=OK step=qemu_cleanlog plc=plctest1_vplc20 force=False
TRACE: 1 22-24-47->1s=0:00:01.113215s status=OK step=qemu_start plc=plctest1_vplc20 force=False
TRACE: 1 22-24-48->0s=0:00:00.814996s status=OK step=qemu_timestamp plc=plctest1_vplc20 force=False
TRACE: 1 22-24-48->0s=0:00:00.603891s status=OK step=qemu_nodefamily plc=plctest1_vplc20 force=False
TRACE: 1 22-24-49->8s=0:00:08.078107s status=OK step=sfa_install_all plc=plctest1_vplc20 force=False
TRACE: 1 22-24-57->0s=0:00:00.580517s status=OK step=sfa_configure plc=plctest1_vplc20 force=False
TRACE: 1 22-24-58->0s=0:00:00.000141s status=OK step=cross_sfa_configure plc=plctest1_vplc20 force=False
TRACE: 1 22-24-58->3s=0:00:03.277378s status=OK step=sfa_start plc=plctest1_vplc20 force=False
TRACE: 1 22-25-01->3s=0:00:03.177705s status=OK step=sfa_import plc=plctest1_vplc20 force=False
TRACE: 1 22-25-04->0s=0:00:00.547600s status=OK step=sfi_configure plc=plctest1_vplc20 force=False
TRACE: 1 22-25-05->1s=0:00:01.271303s status=OK step=sfa_register_site plc=plctest1_vplc20 force=False
TRACE: 1 22-25-06->2s=0:00:02.343990s status=OK step=sfa_register_pi plc=plctest1_vplc20 force=False
TRACE: 1 22-25-08->1s=0:00:01.672674s status=OK step=sfa_register_user plc=plctest1_vplc20 force=False
TRACE: 1 22-25-10->0s=0:00:00.821720s status=OK step=sfa_update_user plc=plctest1_vplc20 force=False
TRACE: 1 22-25-11->0s=0:00:00.972916s status=OK step=sfa_register_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-25-12->3s=0:00:03.686089s status=OK step=sfa_renew_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-25-16->0s=0:00:00.972525s status=OK step=sfa_remove_user_from_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-25-17->0s=0:00:00.770939s status=OK step=sfi_show_slice_researchers plc=plctest1_vplc20 force=False
TRACE: 1 22-25-17->0s=0:00:00.821325s status=OK step=sfa_insert_user_in_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-25-18->0s=0:00:00.770040s status=OK step=sfi_show_slice_researchers plc=plctest1_vplc20 force=False
TRACE: 1 22-25-19->0s=0:00:00.772126s status=OK step=sfa_discover plc=plctest1_vplc20 force=False
TRACE: 1 22-25-20->1s=0:00:01.090739s status=OK step=sfa_rspec plc=plctest1_vplc20 force=False
TRACE: 1 22-25-21->1s=0:00:01.171814s status=OK step=sfa_allocate plc=plctest1_vplc20 force=False
TRACE: 1 22-25-22->1s=0:00:01.120802s status=OK step=sfa_provision plc=plctest1_vplc20 force=False
TRACE: 1 22-25-23->0s=0:00:00.770600s status=OK step=sfa_describe plc=plctest1_vplc20 force=False
TRACE: 1 22-25-24->0s=0:00:00.047236s status=OK step=sfa_check_slice_plc plc=plctest1_vplc20 force=False
TRACE: 1 22-25-24->2s=0:00:02.292660s status=OK step=sfa_update_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-25-26->1s=0:00:01.591963s status=OK step=sfi_list plc=plctest1_vplc20 force=False
TRACE: 1 22-25-28->0s=0:00:00.770230s status=OK step=sfi_show_site plc=plctest1_vplc20 force=False
TRACE: 1 22-25-28->3s=0:00:03.263993s status=OK step=sfa_utest plc=plctest1_vplc20 force=False
TRACE: 1 22-25-32->0s=0:00:00.268548s status=OK step=probe_kvm_iptables plc=plctest1_vplc20 force=False
TRACE: 1 22-25-32->0s=0:00:00.010642s status=OK step=ping_node plc=plctest1_vplc20 force=False
TRACE: 1 22-25-32->30s=0:00:30.575872s status=OK step=ssh_node_debug plc=plctest1_vplc20 force=False
TRACE: 1 22-26-03->2s=0:00:02.244086s status=OK step=plcsh_stress_test plc=plctest1_vplc20 force=False
TRACE: 1 22-26-05->217s=0:03:37.146645s status=OK step=ssh_node_boot plc=plctest1_vplc20 force=False
TRACE: 1 22-29-42->0s=0:00:00.470594s status=OK step=node_bmlogs plc=plctest1_vplc20 force=False
TRACE: 1 22-29-42->1s=0:00:01.057681s status=OK step=ssh_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-29-44->4s=0:00:04.529351s status=OK step=ssh_slice_basics plc=plctest1_vplc20 force=False
TRACE: 1 22-29-48->0s=0:00:00.319083s status=OK step=ssh_slice_sfa plc=plctest1_vplc20 force=False
TRACE: 1 22-29-48->0s=0:00:00.268424s status=OK step=sfa_rspec_empty plc=plctest1_vplc20 force=False
TRACE: 1 22-29-49->1s=0:00:01.121277s status=OK step=sfa_allocate_empty plc=plctest1_vplc20 force=False
TRACE: 1 22-29-50->1s=0:00:01.071930s status=OK step=sfa_provision_empty plc=plctest1_vplc20 force=False
TRACE: 1 22-29-51->0s=0:00:00.026869s status=OK step=sfa_check_slice_plc_empty plc=plctest1_vplc20 force=False
TRACE: 1 22-29-51->1s=0:00:01.541889s status=OK step=sfa_delete_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-29-52->0s=0:00:00.820781s status=OK step=sfa_delete_user plc=plctest1_vplc20 force=False
TRACE: 1 22-29-53->4s=0:00:04.414988s status=OK step=cross_check_tcp plc=plctest1_vplc20 force=False
TRACE: 1 22-29-58->0s=0:00:00.437420s status=OK step=check_system_slice plc=plctest1_vplc20 force=False
TRACE: 1 22-29-58->0s=0:00:00.269240s status=OK step=debug_nodemanager plc=plctest1_vplc20 force=False
TRACE: 1 22-29-58->0s=0:00:00.167498s status=OK step=empty_slices plc=plctest1_vplc20 force=False
TRACE: 1 22-29-59->160s=0:02:40.779933s status=OK step=ssh_slice_off plc=plctest1_vplc20 force=False
TRACE: 1 22-32-39->15s=0:00:15.832514s status=OK[I] step=slice_fs_deleted_ignore plc=plctest1_vplc20 force=False
TRACE: 1 22-32-55->0s=0:00:00.120535s status=OK step=fill_slices plc=plctest1_vplc20 force=False
TRACE: 1 22-32-55->31s=0:00:31.743161s status=OK step=ssh_slice_again plc=plctest1_vplc20 force=False
TRACE: 1 22-33-27->4s=0:00:04.273845s status=OK step=gather_logs plc=plctest1_vplc20 force=True