-> system returns 0
Attempting to set passwd for person_id=4 in DB2UPDATE 1
-> system returns 0
-+++ 19 seconds ellapsed
++++ 13.24 seconds ellapsed (13.24)
01:== Created site 2 with max_slices=4
02:== Created site 2 with max_slices=4
01:== Created site 3 with max_slices=4
01:== Created site 5 with max_slices=4
02:== Created site 5 with max_slices=4
=== refresh after site creation
-+++ 39 seconds ellapsed
++++ 24.84 seconds ellapsed (11.61)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 4, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 1, 'new_nodes': 0}
-+++ 44 seconds ellapsed
++++ 27.08 seconds ellapsed (2.24)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 4, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 1, 'new_nodes': 0}
-+++ 50 seconds ellapsed
-+++ 50 seconds ellapsed
++++ 28.53 seconds ellapsed (1.45)
++++ 28.53 seconds ellapsed (0.00)
=== refresh before persons&keys creation
-+++ 56 seconds ellapsed
++++ 32.29 seconds ellapsed (3.76)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 62 seconds ellapsed
++++ 34.52 seconds ellapsed (2.23)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 67 seconds ellapsed
++++ 36.07 seconds ellapsed (1.55)
01: Checking keys: got 0 local (e=0) & 0 foreign (e=0)
02: Checking keys: got 0 local (e=0) & 0 foreign (e=0)
01: Checking persons: got 4 local (e=4) & 1 foreign (e=1)
01: Checking persons: got 8 local (e=8) & 1 foreign (e=1)
02: Checking persons: got 8 local (e=8) & 1 foreign (e=1)
=== refresh after persons&keys creation
-+++ 117 seconds ellapsed
++++ 58.93 seconds ellapsed (22.86)
01:== Refreshing peer got {'new_keys': 8, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 4, 'new_nodes': 0}
-+++ 123 seconds ellapsed
++++ 61.32 seconds ellapsed (2.39)
02:== Refreshing peer got {'new_keys': 8, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 4, 'new_nodes': 0}
-+++ 129 seconds ellapsed
++++ 63.01 seconds ellapsed (1.70)
01: Checking keys: got 8 local (e=8) & 8 foreign (e=8)
02: Checking keys: got 8 local (e=8) & 8 foreign (e=8)
01: Checking persons: got 8 local (e=8) & 5 foreign (e=5)
02: Checking persons: got 8 local (e=8) & 5 foreign (e=5)
-+++ 134 seconds ellapsed
++++ 65.41 seconds ellapsed (2.40)
==================== ('RESETTING NODES',)
01:== Cleaning all nodes
02:== Cleaning all nodes
=== refresh cleaned nodes
-+++ 135 seconds ellapsed
++++ 66.35 seconds ellapsed (0.94)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 142 seconds ellapsed
++++ 68.67 seconds ellapsed (2.32)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 147 seconds ellapsed
++++ 70.77 seconds ellapsed (2.10)
01: Checking nodes: got 0 local (e=0) & 0 foreign (e=0)
02: Checking nodes: got 0 local (e=0) & 0 foreign (e=0)
==================== ('CREATING NODES',)
01: Checking nodes: got 5 local (e=5) & 0 foreign (e=0)
02: Checking nodes: got 5 local (e=5) & 0 foreign (e=0)
=== refresh after node creation
-+++ 168 seconds ellapsed
++++ 82.39 seconds ellapsed (11.63)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 5}
-+++ 176 seconds ellapsed
++++ 84.92 seconds ellapsed (2.53)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 5}
-+++ 182 seconds ellapsed
++++ 86.84 seconds ellapsed (1.92)
01: Checking nodes: got 5 local (e=5) & 5 foreign (e=5)
02: Checking nodes: got 5 local (e=5) & 5 foreign (e=5)
02:== Deleted node 1, returns 1
02:== Deleted node 20, returns 1
02: Checking nodes: got 0 local (e=0) & 5 foreign (e=5)
=== refresh after deletion on plc2
-+++ 224 seconds ellapsed
++++ 94.94 seconds ellapsed (8.09)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': -5}
-+++ 231 seconds ellapsed
++++ 97.35 seconds ellapsed (2.42)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 237 seconds ellapsed
++++ 99.28 seconds ellapsed (1.93)
01: Checking nodes: got 5 local (e=5) & 0 foreign (e=0)
02: Checking nodes: got 0 local (e=0) & 5 foreign (e=5)
==================== ('ADD on plc2 for different indexes',)
01: Checking nodes: got 5 local (e=5) & 0 foreign (e=0)
02: Checking nodes: got 5 local (e=5) & 5 foreign (e=5)
=== refresh after re-creation on plc2
-+++ 247 seconds ellapsed
++++ 102.83 seconds ellapsed (3.54)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 5}
-+++ 254 seconds ellapsed
++++ 105.35 seconds ellapsed (2.52)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 260 seconds ellapsed
++++ 107.23 seconds ellapsed (1.88)
01: Checking nodes: got 5 local (e=5) & 5 foreign (e=5)
02: Checking nodes: got 5 local (e=5) & 5 foreign (e=5)
-+++ 262 seconds ellapsed
++++ 108.51 seconds ellapsed (1.28)
==================== ('RESETTING SLICES TEST',)
01:== Cleaning all nodes
01:==== Cleaning node 1
02:== Cleaning all slices
02:==== Cleaning slice 3
=== refresh After slices init
-+++ 293 seconds ellapsed
++++ 125.98 seconds ellapsed (17.47)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 300 seconds ellapsed
++++ 128.52 seconds ellapsed (2.54)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 306 seconds ellapsed
++++ 130.38 seconds ellapsed (1.85)
==================== ('CREATING SLICES on plc1',)
01:== created slice 4 - max nodes=5
01:== Attached person user1-1@plc1.org to slice oneone_slice1
01: Checking slices: got 6 local (e=6) & 0 foreign (e=0)
02: Checking slices: got 2 local (e=2) & 0 foreign (e=0)
=== refresh after slice created on plc1
-+++ 334 seconds ellapsed
++++ 152.20 seconds ellapsed (21.82)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 343 seconds ellapsed
++++ 154.71 seconds ellapsed (2.51)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 4, 'new_persons': 0, 'new_nodes': 0}
-+++ 350 seconds ellapsed
++++ 156.64 seconds ellapsed (1.93)
01: Checking slices: got 6 local (e=6) & 0 foreign (e=0)
02: Checking slices: got 2 local (e=2) & 4 foreign (e=4)
01: local slice oneone_slice1 (e=0) on nodes []
02: foreign slice onethree_slice3 (e=0) on nodes []
02: foreign slice onefour_slice4 (e=0) on nodes []
=== refresh After local nodes were added on plc1
-+++ 390 seconds ellapsed
++++ 181.07 seconds ellapsed (24.44)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 397 seconds ellapsed
++++ 183.59 seconds ellapsed (2.52)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 403 seconds ellapsed
++++ 185.52 seconds ellapsed (1.93)
01: local slice oneone_slice1 (e=5) on nodes [16, 17, 18, 19, 20]
[LOC:5] : n101.plc1.org n102.plc1.org n103.plc1.org n104.plc1.org n105.plc1.org
01: local slice onetwo_slice2 (e=5) on nodes [16, 17, 18, 19, 20]
02: foreign slice onefour_slice4 (e=5) on nodes [8, 9, 10, 6, 7]
[FOR:5] : n101.plc1.org n102.plc1.org n103.plc1.org n104.plc1.org n105.plc1.org
=== refresh After foreign nodes were added in plc1
-+++ 444 seconds ellapsed
++++ 209.31 seconds ellapsed (23.79)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 451 seconds ellapsed
++++ 211.86 seconds ellapsed (2.55)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 457 seconds ellapsed
++++ 213.88 seconds ellapsed (2.02)
01: local slice oneone_slice1 (e=10) on nodes [16, 17, 18, 19, 20, 11, 12, 13, 14, 15]
[LOC:5] : n101.plc1.org n102.plc1.org n103.plc1.org n104.plc1.org n105.plc1.org
[FOR:5] : n201.plc2.org n202.plc2.org n203.plc2.org n204.plc2.org n205.plc2.org
'name': 'onefour_slice4',
'slice_id': 7}
=== refresh After foreign nodes were removed on plc1
-+++ 507 seconds ellapsed
++++ 240.71 seconds ellapsed (26.83)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 514 seconds ellapsed
++++ 243.24 seconds ellapsed (2.53)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 520 seconds ellapsed
++++ 245.17 seconds ellapsed (1.93)
01: local slice oneone_slice1 (e=5) on nodes [16, 17, 18, 19, 20]
[LOC:5] : n101.plc1.org n102.plc1.org n103.plc1.org n104.plc1.org n105.plc1.org
01: local slice onetwo_slice2 (e=5) on nodes [16, 17, 18, 19, 20]
02: foreign slice onefour_slice4 (e=5) on nodes [8, 9, 10, 6, 7]
[FOR:5] : n101.plc1.org n102.plc1.org n103.plc1.org n104.plc1.org n105.plc1.org
=== refresh After local nodes were removed on plc1
-+++ 558 seconds ellapsed
++++ 267.60 seconds ellapsed (22.43)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 564 seconds ellapsed
++++ 270.09 seconds ellapsed (2.49)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 571 seconds ellapsed
++++ 272.02 seconds ellapsed (1.92)
01: local slice oneone_slice1 (e=0) on nodes []
01: local slice onetwo_slice2 (e=0) on nodes []
01: local slice onethree_slice3 (e=0) on nodes []
01: Checking slices: got 2 local (e=2) & 0 foreign (e=0)
02: Checking slices: got 2 local (e=2) & 4 foreign (e=4)
=== refresh After slices clenaup
-+++ 593 seconds ellapsed
++++ 286.11 seconds ellapsed (14.09)
01:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc1', 'new_slices': 0, 'new_persons': 0, 'new_nodes': 0}
-+++ 600 seconds ellapsed
++++ 288.65 seconds ellapsed (2.54)
02:== Refreshing peer got {'new_keys': 0, 'new_sites': 0, 'plcname': 'Thierry plc2 on devbox', 'new_slices': -4, 'new_persons': 0, 'new_nodes': 0}
-+++ 606 seconds ellapsed
++++ 290.56 seconds ellapsed (1.91)
01: Checking slices: got 2 local (e=2) & 0 foreign (e=0)
02: Checking slices: got 2 local (e=2) & 0 foreign (e=0)
-+++ 609 seconds ellapsed
++++ 292.44 seconds ellapsed (1.88)
==================== ('END',)