TRACE: 1 09-49-53->0s=0:00:00.000246s status=OK step=show plc=plctest1_vplc05 force=False
TRACE: 1 09-49-53->1s=0:00:01.445170s status=OK step=plcvm_delete plc=plctest1_vplc05 force=False
TRACE: 1 09-49-55->0s=0:00:00.534950s status=OK step=plcvm_timestamp plc=plctest1_vplc05 force=False
TRACE: 1 09-49-55->28s=0:00:28.477806s status=OK step=plcvm_create plc=plctest1_vplc05 force=False
TRACE: 1 09-50-24->32s=0:00:32.337465s status=OK step=plc_install plc=plctest1_vplc05 force=False
TRACE: 1 09-50-56->0s=0:00:00.638272s status=OK step=plc_configure plc=plctest1_vplc05 force=False
TRACE: 1 09-50-57->37s=0:00:37.374272s status=OK step=plc_start plc=plctest1_vplc05 force=False
TRACE: 1 09-51-34->0s=0:00:00.534909s status=OK step=keys_fetch plc=plctest1_vplc05 force=False
TRACE: 1 09-51-35->0s=0:00:00.001548s status=OK step=keys_store plc=plctest1_vplc05 force=False
TRACE: 1 09-51-35->0s=0:00:00.009421s status=OK step=keys_clear_known_hosts plc=plctest1_vplc05 force=False
TRACE: 1 09-51-35->0s=0:00:00.778767s status=OK step=plcapi_urls plc=plctest1_vplc05 force=False
TRACE: 1 09-51-35->0s=0:00:00.590673s status=OK step=speed_up_slices plc=plctest1_vplc05 force=False
TRACE: 1 09-51-36->0s=0:00:00.028506s status=OK step=initscripts plc=plctest1_vplc05 force=False
TRACE: 1 09-51-36->1s=0:00:01.420898s status=OK step=sites plc=plctest1_vplc05 force=False
TRACE: 1 09-51-37->0s=0:00:00.176353s status=OK step=nodes plc=plctest1_vplc05 force=False
TRACE: 1 09-51-38->0s=0:00:00.797459s status=OK step=slices plc=plctest1_vplc05 force=False
TRACE: 1 09-51-38->0s=0:00:00.157424s status=OK step=nodegroups plc=plctest1_vplc05 force=False
TRACE: 1 09-51-39->0s=0:00:00.023793s status=OK step=leases plc=plctest1_vplc05 force=False
TRACE: 1 09-51-39->0s=0:00:00.095747s status=OK[I] step=check_vsys_defaults_ignore plc=plctest1_vplc05 force=False
TRACE: 1 09-51-39->0s=0:00:00.537878s status=OK step=qemu_kill_mine plc=plctest1_vplc05 force=False
TRACE: 1 09-51-39->0s=0:00:00.046198s status=OK step=nodestate_reinstall plc=plctest1_vplc05 force=False
TRACE: 1 09-51-39->0s=0:00:00.084528s status=OK step=qemu_local_init plc=plctest1_vplc05 force=False
TRACE: 1 09-51-39->3s=0:00:03.892966s status=OK step=bootcd plc=plctest1_vplc05 force=False
TRACE: 1 09-51-43->0s=0:00:00.032869s status=OK step=qemu_local_config plc=plctest1_vplc05 force=False
TRACE: 1 09-51-43->0s=0:00:00.269670s status=OK step=qemu_clean_mine plc=plctest1_vplc05 force=False
TRACE: 1 09-51-44->1s=0:00:01.439384s status=OK step=qemu_export plc=plctest1_vplc05 force=False
TRACE: 1 09-51-45->0s=0:00:00.538287s status=OK step=qemu_cleanlog plc=plctest1_vplc05 force=False
TRACE: 1 09-51-46->0s=0:00:00.958213s status=OK step=qemu_start plc=plctest1_vplc05 force=False
TRACE: 1 09-51-46->0s=0:00:00.807494s status=OK step=qemu_timestamp plc=plctest1_vplc05 force=False
TRACE: 1 09-51-47->0s=0:00:00.553237s status=OK step=qemu_nodefamily plc=plctest1_vplc05 force=False
TRACE: 1 09-51-48->6s=0:00:06.322194s status=OK step=sfa_install_all plc=plctest1_vplc05 force=False
TRACE: 1 09-51-54->0s=0:00:00.539058s status=OK step=sfa_configure plc=plctest1_vplc05 force=False
TRACE: 1 09-51-55->0s=0:00:00.000148s status=OK step=cross_sfa_configure plc=plctest1_vplc05 force=False
TRACE: 1 09-51-55->6s=0:00:06.704004s status=OK step=sfa_start plc=plctest1_vplc05 force=False
TRACE: 1 09-52-01->2s=0:00:02.724684s status=OK step=sfa_import plc=plctest1_vplc05 force=False
TRACE: 1 09-52-04->0s=0:00:00.556263s status=OK step=sfi_configure plc=plctest1_vplc05 force=False
TRACE: 1 09-52-05->1s=0:00:01.220348s status=OK step=sfa_register_site plc=plctest1_vplc05 force=False
TRACE: 1 09-52-06->1s=0:00:01.842374s status=OK step=sfa_register_pi plc=plctest1_vplc05 force=False
TRACE: 1 09-52-08->1s=0:00:01.773492s status=OK step=sfa_register_user plc=plctest1_vplc05 force=False
TRACE: 1 09-52-10->0s=0:00:00.619725s status=OK step=sfa_update_user plc=plctest1_vplc05 force=False
TRACE: 1 09-52-10->0s=0:00:00.970209s status=OK step=sfa_register_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-52-11->3s=0:00:03.279984s status=OK step=sfa_renew_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-52-14->0s=0:00:00.920524s status=OK step=sfa_remove_user_from_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-52-15->0s=0:00:00.669767s status=OK step=sfi_show_slice_researchers plc=plctest1_vplc05 force=False
TRACE: 1 09-52-16->0s=0:00:00.719886s status=OK step=sfa_insert_user_in_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-52-17->0s=0:00:00.669482s status=OK step=sfi_show_slice_researchers plc=plctest1_vplc05 force=False
TRACE: 1 09-52-17->0s=0:00:00.719569s status=OK step=sfa_discover plc=plctest1_vplc05 force=False
TRACE: 1 09-52-18->0s=0:00:00.938335s status=OK step=sfa_rspec plc=plctest1_vplc05 force=False
TRACE: 1 09-52-19->1s=0:00:01.070827s status=OK step=sfa_allocate plc=plctest1_vplc05 force=False
TRACE: 1 09-52-20->0s=0:00:00.970234s status=OK step=sfa_provision plc=plctest1_vplc05 force=False
TRACE: 1 09-52-21->0s=0:00:00.720360s status=OK step=sfa_describe plc=plctest1_vplc05 force=False
TRACE: 1 09-52-22->0s=0:00:00.065072s status=OK step=sfa_check_slice_plc plc=plctest1_vplc05 force=False
TRACE: 1 09-52-22->1s=0:00:01.991618s status=OK step=sfa_update_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-52-24->1s=0:00:01.439773s status=OK step=sfi_list plc=plctest1_vplc05 force=False
TRACE: 1 09-52-25->0s=0:00:00.719641s status=OK step=sfi_show_site plc=plctest1_vplc05 force=False
TRACE: 1 09-52-26->3s=0:00:03.865815s status=OK step=sfa_utest plc=plctest1_vplc05 force=False
TRACE: 1 09-52-30->0s=0:00:00.267978s status=OK step=probe_kvm_iptables plc=plctest1_vplc05 force=False
TRACE: 1 09-52-30->0s=0:00:00.009780s status=OK step=ping_node plc=plctest1_vplc05 force=False
TRACE: 1 09-52-30->0s=0:00:00.117113s status=OK step=ssh_node_debug plc=plctest1_vplc05 force=False
TRACE: 1 09-52-30->1s=0:00:01.739419s status=OK step=plcsh_stress_test plc=plctest1_vplc05 force=False
TRACE: 1 09-52-32->141s=0:02:21.218962s status=OK step=ssh_node_boot plc=plctest1_vplc05 force=False
TRACE: 1 09-54-53->0s=0:00:00.368508s status=OK step=node_bmlogs plc=plctest1_vplc05 force=False
TRACE: 1 09-54-54->16s=0:00:16.003063s status=OK step=ssh_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-55-10->3s=0:00:03.824775s status=OK step=ssh_slice_basics plc=plctest1_vplc05 force=False
TRACE: 1 09-55-13->0s=0:00:00.436005s status=OK step=check_initscripts plc=plctest1_vplc05 force=False
TRACE: 1 09-55-14->0s=0:00:00.218072s status=OK step=ssh_slice_sfa plc=plctest1_vplc05 force=False
TRACE: 1 09-55-14->0s=0:00:00.267325s status=OK step=sfa_rspec_empty plc=plctest1_vplc05 force=False
TRACE: 1 09-55-14->1s=0:00:01.021180s status=OK step=sfa_allocate_empty plc=plctest1_vplc05 force=False
TRACE: 1 09-55-15->0s=0:00:00.920614s status=OK step=sfa_provision_empty plc=plctest1_vplc05 force=False
TRACE: 1 09-55-16->0s=0:00:00.032607s status=OK step=sfa_check_slice_plc_empty plc=plctest1_vplc05 force=False
TRACE: 1 09-55-16->1s=0:00:01.389388s status=OK step=sfa_delete_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-55-18->0s=0:00:00.669821s status=OK step=sfa_delete_user plc=plctest1_vplc05 force=False
TRACE: 1 09-55-18->2s=0:00:02.845346s status=OK step=cross_check_tcp plc=plctest1_vplc05 force=False
TRACE: 1 09-55-21->0s=0:00:00.455598s status=OK step=check_system_slice plc=plctest1_vplc05 force=False
TRACE: 1 09-55-22->0s=0:00:00.267556s status=OK step=debug_nodemanager plc=plctest1_vplc05 force=False
TRACE: 1 09-55-22->0s=0:00:00.211460s status=OK step=empty_slices plc=plctest1_vplc05 force=False
TRACE: 1 09-55-22->47s=0:00:47.331712s status=OK step=ssh_slice_off plc=plctest1_vplc05 force=False
TRACE: 1 09-56-09->0s=0:00:00.351607s status=OK[I] step=slice_fs_deleted_ignore plc=plctest1_vplc05 force=False
TRACE: 1 09-56-10->0s=0:00:00.279077s status=OK step=fill_slices plc=plctest1_vplc05 force=False
TRACE: 1 09-56-10->31s=0:00:31.436490s status=OK step=ssh_slice_again plc=plctest1_vplc05 force=False
TRACE: 1 09-56-42->2s=0:00:02.013017s status=OK step=gather_logs plc=plctest1_vplc05 force=True