TRACE: 1 22-25-26->0s=0:00:00.000235s status=OK step=show plc=plctest1_vplc21 force=False
TRACE: 1 22-25-26->1s=0:00:01.400707s status=OK step=plcvm_delete plc=plctest1_vplc21 force=False
TRACE: 1 22-25-27->0s=0:00:00.535534s status=OK step=plcvm_timestamp plc=plctest1_vplc21 force=False
TRACE: 1 22-25-28->30s=0:00:30.290098s status=OK step=plcvm_create plc=plctest1_vplc21 force=False
TRACE: 1 22-25-58->72s=0:01:12.163133s status=OK step=plc_install plc=plctest1_vplc21 force=False
TRACE: 1 22-27-10->0s=0:00:00.730710s status=OK step=plc_configure plc=plctest1_vplc21 force=False
TRACE: 1 22-27-11->20s=0:00:20.926216s status=OK step=plc_start plc=plctest1_vplc21 force=False
TRACE: 1 22-27-32->0s=0:00:00.537411s status=OK step=keys_fetch plc=plctest1_vplc21 force=False
TRACE: 1 22-27-33->0s=0:00:00.001750s status=OK step=keys_store plc=plctest1_vplc21 force=False
TRACE: 1 22-27-33->0s=0:00:00.009923s status=OK step=keys_clear_known_hosts plc=plctest1_vplc21 force=False
TRACE: 1 22-27-33->0s=0:00:00.372268s status=OK step=plcapi_urls plc=plctest1_vplc21 force=False
TRACE: 1 22-27-33->0s=0:00:00.309039s status=OK step=speed_up_slices plc=plctest1_vplc21 force=False
TRACE: 1 22-27-33->0s=0:00:00.018198s status=OK step=initscripts plc=plctest1_vplc21 force=False
TRACE: 1 22-27-33->1s=0:00:01.012329s status=OK step=sites plc=plctest1_vplc21 force=False
TRACE: 1 22-27-34->0s=0:00:00.141178s status=OK step=nodes plc=plctest1_vplc21 force=False
TRACE: 1 22-27-35->0s=0:00:00.538086s status=OK step=slices plc=plctest1_vplc21 force=False
TRACE: 1 22-27-35->0s=0:00:00.123995s status=OK step=nodegroups plc=plctest1_vplc21 force=False
TRACE: 1 22-27-35->0s=0:00:00.016377s status=OK step=leases plc=plctest1_vplc21 force=False
TRACE: 1 22-27-35->0s=0:00:00.074918s status=OK[I] step=check_vsys_defaults_ignore plc=plctest1_vplc21 force=False
TRACE: 1 22-27-35->0s=0:00:00.490060s status=OK step=qemu_kill_mine plc=plctest1_vplc21 force=False
TRACE: 1 22-27-36->0s=0:00:00.044254s status=OK step=nodestate_reinstall plc=plctest1_vplc21 force=False
TRACE: 1 22-27-36->0s=0:00:00.020487s status=OK step=qemu_local_init plc=plctest1_vplc21 force=False
TRACE: 1 22-27-36->7s=0:00:07.243272s status=OK step=bootcd plc=plctest1_vplc21 force=False
TRACE: 1 22-27-43->0s=0:00:00.069595s status=OK step=qemu_local_config plc=plctest1_vplc21 force=False
TRACE: 1 22-27-43->0s=0:00:00.269941s status=OK step=qemu_clean_mine plc=plctest1_vplc21 force=False
TRACE: 1 22-27-43->2s=0:00:02.744391s status=OK step=qemu_export plc=plctest1_vplc21 force=False
TRACE: 1 22-27-46->0s=0:00:00.539391s status=OK step=qemu_cleanlog plc=plctest1_vplc21 force=False
TRACE: 1 22-27-47->0s=0:00:00.910253s status=OK step=qemu_start plc=plctest1_vplc21 force=False
TRACE: 1 22-27-48->0s=0:00:00.810935s status=OK step=qemu_timestamp plc=plctest1_vplc21 force=False
TRACE: 1 22-27-48->0s=0:00:00.560053s status=OK step=qemu_nodefamily plc=plctest1_vplc21 force=False
TRACE: 1 22-27-49->8s=0:00:08.432822s status=OK step=sfa_install_all plc=plctest1_vplc21 force=False
TRACE: 1 22-27-57->0s=0:00:00.634465s status=OK step=sfa_configure plc=plctest1_vplc21 force=False
TRACE: 1 22-27-58->0s=0:00:00.000121s status=OK step=cross_sfa_configure plc=plctest1_vplc21 force=False
TRACE: 1 22-27-58->3s=0:00:03.678662s status=OK step=sfa_start plc=plctest1_vplc21 force=False
TRACE: 1 22-28-02->3s=0:00:03.377200s status=OK step=sfa_import plc=plctest1_vplc21 force=False
TRACE: 1 22-28-05->0s=0:00:00.549518s status=OK step=sfi_configure plc=plctest1_vplc21 force=False
TRACE: 1 22-28-06->1s=0:00:01.071130s status=OK step=sfa_register_site plc=plctest1_vplc21 force=False
TRACE: 1 22-28-07->2s=0:00:02.293723s status=OK step=sfa_register_pi plc=plctest1_vplc21 force=False
TRACE: 1 22-28-09->1s=0:00:01.673503s status=OK step=sfa_register_user plc=plctest1_vplc21 force=False
TRACE: 1 22-28-11->0s=0:00:00.720547s status=OK step=sfa_update_user plc=plctest1_vplc21 force=False
TRACE: 1 22-28-11->0s=0:00:00.921355s status=OK step=sfa_register_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-28-12->3s=0:00:03.834970s status=OK step=sfa_renew_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-28-16->0s=0:00:00.970331s status=OK step=sfa_remove_user_from_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-28-17->0s=0:00:00.869806s status=OK step=sfi_show_slice_researchers plc=plctest1_vplc21 force=False
TRACE: 1 22-28-18->0s=0:00:00.870816s status=OK step=sfa_insert_user_in_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-28-19->0s=0:00:00.819578s status=OK step=sfi_show_slice_researchers plc=plctest1_vplc21 force=False
TRACE: 1 22-28-20->0s=0:00:00.871102s status=OK step=sfa_discover plc=plctest1_vplc21 force=False
TRACE: 1 22-28-21->1s=0:00:01.140172s status=OK step=sfa_rspec plc=plctest1_vplc21 force=False
TRACE: 1 22-28-22->1s=0:00:01.222354s status=OK step=sfa_allocate plc=plctest1_vplc21 force=False
TRACE: 1 22-28-23->1s=0:00:01.121648s status=OK step=sfa_provision plc=plctest1_vplc21 force=False
TRACE: 1 22-28-24->0s=0:00:00.820178s status=OK step=sfa_describe plc=plctest1_vplc21 force=False
TRACE: 1 22-28-25->0s=0:00:00.047632s status=OK step=sfa_check_slice_plc plc=plctest1_vplc21 force=False
TRACE: 1 22-28-25->2s=0:00:02.243005s status=OK step=sfa_update_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-28-27->1s=0:00:01.640748s status=OK step=sfi_list plc=plctest1_vplc21 force=False
TRACE: 1 22-28-29->0s=0:00:00.820680s status=OK step=sfi_show_site plc=plctest1_vplc21 force=False
TRACE: 1 22-28-30->3s=0:00:03.364892s status=OK step=sfa_utest plc=plctest1_vplc21 force=False
TRACE: 1 22-28-33->0s=0:00:00.268135s status=OK step=probe_kvm_iptables plc=plctest1_vplc21 force=False
TRACE: 1 22-28-33->0s=0:00:00.010753s status=OK step=ping_node plc=plctest1_vplc21 force=False
TRACE: 1 22-28-33->30s=0:00:30.634652s status=OK step=ssh_node_debug plc=plctest1_vplc21 force=False
TRACE: 1 22-29-04->2s=0:00:02.241773s status=OK step=plcsh_stress_test plc=plctest1_vplc21 force=False
TRACE: 1 22-29-06->186s=0:03:06.905676s status=OK step=ssh_node_boot plc=plctest1_vplc21 force=False
TRACE: 1 22-32-13->0s=0:00:00.419828s status=OK step=node_bmlogs plc=plctest1_vplc21 force=False
TRACE: 1 22-32-13->1s=0:00:01.810121s status=OK step=ssh_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-32-15->6s=0:00:06.138787s status=OK step=ssh_slice_basics plc=plctest1_vplc21 force=False
TRACE: 1 22-32-21->0s=0:00:00.319031s status=OK step=ssh_slice_sfa plc=plctest1_vplc21 force=False
TRACE: 1 22-32-22->0s=0:00:00.268474s status=OK step=sfa_rspec_empty plc=plctest1_vplc21 force=False
TRACE: 1 22-32-22->1s=0:00:01.173009s status=OK step=sfa_allocate_empty plc=plctest1_vplc21 force=False
TRACE: 1 22-32-23->1s=0:00:01.072973s status=OK step=sfa_provision_empty plc=plctest1_vplc21 force=False
TRACE: 1 22-32-24->0s=0:00:00.025851s status=OK step=sfa_check_slice_plc_empty plc=plctest1_vplc21 force=False
TRACE: 1 22-32-24->1s=0:00:01.542531s status=OK step=sfa_delete_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-32-26->0s=0:00:00.770680s status=OK step=sfa_delete_user plc=plctest1_vplc21 force=False
TRACE: 1 22-32-27->15s=0:00:15.397167s status=OK step=cross_check_tcp plc=plctest1_vplc21 force=False
TRACE: 1 22-32-42->0s=0:00:00.436971s status=OK step=check_system_slice plc=plctest1_vplc21 force=False
TRACE: 1 22-32-42->0s=0:00:00.268363s status=OK step=debug_nodemanager plc=plctest1_vplc21 force=False
TRACE: 1 22-32-43->0s=0:00:00.174075s status=OK step=empty_slices plc=plctest1_vplc21 force=False
TRACE: 1 22-32-43->160s=0:02:40.774355s status=OK step=ssh_slice_off plc=plctest1_vplc21 force=False
TRACE: 1 22-35-24->15s=0:00:15.736650s status=OK[I] step=slice_fs_deleted_ignore plc=plctest1_vplc21 force=False
TRACE: 1 22-35-39->0s=0:00:00.134091s status=OK step=fill_slices plc=plctest1_vplc21 force=False
TRACE: 1 22-35-40->31s=0:00:31.776248s status=OK step=ssh_slice_again plc=plctest1_vplc21 force=False
TRACE: 1 22-36-11->4s=0:00:04.617949s status=OK step=gather_logs plc=plctest1_vplc21 force=True