Feb  5 10:20:30 px1 Controller[1801]: 10:20:30.322 [grizzly-http-server-0] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 102 'RequestThinFreeSpace' send
Feb  5 10:20:30 px1 Satellite[1813]: 10:20:30.322 [MainWorkerPool-7] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 102 'RequestThinFreeSpace' start (seq 102)
Feb  5 10:20:30 px1 Controller[1801]: 10:20:30.323 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 102 answer received (seq 344)
Feb  5 10:20:30 px1 Controller[1801]: 10:20:30.323 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 102 answer received (seq 345)
Feb  5 10:20:30 px1 Controller[1801]: 10:20:30.323 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 102 complete received (seq 346)
Feb  5 10:20:30 px1 Satellite[1813]: 10:20:30.323 [MainWorkerPool-7] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 102 'RequestThinFreeSpace' scope 'Query free space' start
Feb  5 10:20:30 px1 Satellite[1813]: 10:20:30.324 [MainWorkerPool-7] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 102 'RequestThinFreeSpace' scope 'Query free space' end
Feb  5 10:20:30 px1 Satellite[1813]: 10:20:30.324 [MainWorkerPool-7] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 102 'RequestThinFreeSpace' end
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.202 [grizzly-http-server-1] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstVlm' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.202 [grizzly-http-server-1] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstVlm' scope 'Fetch volume allocated' start
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.203 [grizzly-http-server-1] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstVlm' scope 'Fetch volume allocated' end
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.203 [grizzly-http-server-1] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstVlm' scope 'Assemble volume list' start
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.204 [grizzly-http-server-1] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstVlm' scope 'Assemble volume list' end
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.229 [grizzly-http-server-15] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'CrtRscDfn' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.264 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - Loading ObjectProtection (ObjProtPath=/resourcedefinitions/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.265 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - Creating ObjectProtection (ObjProtPath=/resourcedefinitions/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.268 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - ObjectProtection created (ObjProtPath=/resourcedefinitions/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.269 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - Creating AccessControl entry (ObjectPath=/resourcedefinitions/VM-999-DISK-1 Role=PUBLIC AccessType=CONTROL)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.270 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - AccessControl entry created (ObjectPath=/resourcedefinitions/VM-999-DISK-1 Role=PUBLIC AccessType=CONTROL)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.270 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - Loading properties for instance (InstanceName=/resourcedefinitions/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.270 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - Loaded all (0) properties for instance (InstanceName=/resourcedefinitions/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.271 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - Creating RESOURCE_DEFINITIONS (ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.276 [grizzly-http-server-15] TRACE LINSTOR/Controller - SYSTEM - RESOURCE_DEFINITIONS created (ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.295 [grizzly-http-server-2] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'ModRscDfn' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.295 [grizzly-http-server-2] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'ModRscDfn' scope 'Modify resource-definition' start
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.297 [grizzly-http-server-2] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resourcedefinitions/VM-999-DISK-1 Key=DrbdOptions/Net/allow-two-primaries Value=yes)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.317 [grizzly-http-server-2] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resourcedefinitions/VM-999-DISK-1 Key=DrbdOptions/Net/allow-two-primaries Value=yes)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.318 [grizzly-http-server-2] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'ModRscDfn' scope 'Modify resource-definition' end
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.330 [grizzly-http-server-3] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'CrtVlmDfn' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.357 [grizzly-http-server-3] TRACE LINSTOR/Controller - SYSTEM - Loading properties for instance (InstanceName=/volumedefinitions/VM-999-DISK-1/0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.358 [grizzly-http-server-3] TRACE LINSTOR/Controller - SYSTEM - Loaded all (0) properties for instance (InstanceName=/volumedefinitions/VM-999-DISK-1/0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.358 [grizzly-http-server-3] TRACE LINSTOR/Controller - SYSTEM - Creating VOLUME_DEFINITIONS (ResName=vm-999-disk-1 VolNum=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.361 [grizzly-http-server-3] TRACE LINSTOR/Controller - SYSTEM - VOLUME_DEFINITIONS created (ResName=vm-999-disk-1 VolNum=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.363 [grizzly-http-server-3] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/volumedefinitions/VM-999-DISK-1/0 Key=DrbdCurrentGi Value=287FBD4CE1743F2A)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.377 [grizzly-http-server-3] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/volumedefinitions/VM-999-DISK-1/0 Key=DrbdCurrentGi Value=287FBD4CE1743F2A)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.377 [grizzly-http-server-3] INFO  LINSTOR/Controller - SYSTEM - New volume definition with number '0' of resource definition 'vm-999-disk-1' created.
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.396 [grizzly-http-server-4] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'AutoPlaceRsc' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.396 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'AutoPlaceRsc' scope 'Auto-place resource' start
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.397 [grizzly-http-server-4] DEBUG LINSTOR/Controller - SYSTEM - Auto-placing 'vm-999-disk-1' on 2 additional nodes using pool 'drbdpool'
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.430 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loading ObjectProtection (ObjProtPath=/resources/PX1-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.431 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating ObjectProtection (ObjProtPath=/resources/PX1-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.436 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - ObjectProtection created (ObjProtPath=/resources/PX1-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.436 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating AccessControl entry (ObjectPath=/resources/PX1-ADMINISTRATION/VM-999-DISK-1 Role=PUBLIC AccessType=CONTROL)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.437 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - AccessControl entry created (ObjectPath=/resources/PX1-ADMINISTRATION/VM-999-DISK-1 Role=PUBLIC AccessType=CONTROL)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.438 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loading properties for instance (InstanceName=/resources/PX1-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.438 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loaded all (0) properties for instance (InstanceName=/resources/PX1-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.438 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating RESOURCES (NodeName=px1 ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.439 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - RESOURCES created (NodeName=px1 ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.440 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Updating RESOURCE_DEFINITIONS's LAYER_STACK to [DRBD] of (ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.441 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - RESOURCE_DEFINITIONS's LAYER_STACK updated to [DRBD] (ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.441 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Updating RESOURCE_DEFINITIONS's LAYER_STACK to [DRBD, STORAGE] of (ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.442 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - RESOURCE_DEFINITIONS's LAYER_STACK updated to [DRBD, STORAGE] (ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.444 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating DrbdRscDfnData (SuffResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.446 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdRscDfnData created (SuffResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.447 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating LayerResourceId DRBD (id: 8, rscName: vm-999-disk-1, parent: -)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.450 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - LayerResourceId created DRBD (id: 8, rscName: vm-999-disk-1, parent: -)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.450 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating DrbdRscData (LayerRscId=8)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.451 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdRscData created (LayerRscId=8)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.451 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating LayerResourceId STORAGE (id: 9, rscName: vm-999-disk-1, parent: 8)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.451 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - LayerResourceId created STORAGE (id: 9, rscName: vm-999-disk-1, parent: 8)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.452 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resources/PX1-ADMINISTRATION/VM-999-DISK-1 Key=StorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.465 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resources/PX1-ADMINISTRATION/VM-999-DISK-1 Key=StorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.466 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loading properties for instance (InstanceName=/volumes/PX1-ADMINISTRATION/VM-999-DISK-1/0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.466 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loaded all (0) properties for instance (InstanceName=/volumes/PX1-ADMINISTRATION/VM-999-DISK-1/0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.466 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating VOLUMES (NodeName=px1 ResName=vm-999-disk-1 VolNum=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.467 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - VOLUMES created (NodeName=px1 ResName=vm-999-disk-1 VolNum=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.468 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Updating DrbdRscData's flags from [] to [] (LayerRscId=8)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.469 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdRscData's flags updated from [] to [] (LayerRscId=8)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.469 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating DrbdVlmDfnData (SuffResName=vm-999-disk-1, VlmNr=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.469 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdVlmDfnData created (SuffResName=vm-999-disk-1, VlmNr=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.470 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating DrbdVlmData (LayerRscId=8, VlmNr=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.470 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdVlmData created (LayerRscId=8, VlmNr=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.471 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating StorageVolume LVM( rscId: 9, vlmNr:0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.471 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - StorageVolume created LVM( rscId: 9, vlmNr:0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.472 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/volumedefinitions/VM-999-DISK-1/0 Key=DrbdOptions/Disk/rs-discard-granularity Value=8192)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.483 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/volumedefinitions/VM-999-DISK-1/0 Key=DrbdOptions/Disk/rs-discard-granularity Value=8192)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.483 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/volumedefinitions/VM-999-DISK-1/0 Key=DrbdOptions/Disk/discard-zeroes-if-aligned Value=yes)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.493 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/volumedefinitions/VM-999-DISK-1/0 Key=DrbdOptions/Disk/discard-zeroes-if-aligned Value=yes)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.495 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resources/PX1-ADMINISTRATION/VM-999-DISK-1 Key=AutoSelectedStorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.506 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resources/PX1-ADMINISTRATION/VM-999-DISK-1 Key=AutoSelectedStorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.507 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loading ObjectProtection (ObjProtPath=/resources/PX2-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.508 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating ObjectProtection (ObjProtPath=/resources/PX2-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.508 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - ObjectProtection created (ObjProtPath=/resources/PX2-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.508 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating AccessControl entry (ObjectPath=/resources/PX2-ADMINISTRATION/VM-999-DISK-1 Role=PUBLIC AccessType=CONTROL)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.509 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - AccessControl entry created (ObjectPath=/resources/PX2-ADMINISTRATION/VM-999-DISK-1 Role=PUBLIC AccessType=CONTROL)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.509 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loading properties for instance (InstanceName=/resources/PX2-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.509 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loaded all (0) properties for instance (InstanceName=/resources/PX2-ADMINISTRATION/VM-999-DISK-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.509 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating RESOURCES (NodeName=px2 ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.510 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - RESOURCES created (NodeName=px2 ResName=vm-999-disk-1)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.510 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating LayerResourceId DRBD (id: 10, rscName: vm-999-disk-1, parent: -)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.510 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - LayerResourceId created DRBD (id: 10, rscName: vm-999-disk-1, parent: -)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.511 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating DrbdRscData (LayerRscId=10)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.511 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdRscData created (LayerRscId=10)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.511 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating LayerResourceId STORAGE (id: 11, rscName: vm-999-disk-1, parent: 10)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.511 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - LayerResourceId created STORAGE (id: 11, rscName: vm-999-disk-1, parent: 10)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.512 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resources/PX2-ADMINISTRATION/VM-999-DISK-1 Key=StorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.521 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resources/PX2-ADMINISTRATION/VM-999-DISK-1 Key=StorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.521 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loading properties for instance (InstanceName=/volumes/PX2-ADMINISTRATION/VM-999-DISK-1/0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.522 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Loaded all (0) properties for instance (InstanceName=/volumes/PX2-ADMINISTRATION/VM-999-DISK-1/0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.522 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating VOLUMES (NodeName=px2 ResName=vm-999-disk-1 VolNum=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.522 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - VOLUMES created (NodeName=px2 ResName=vm-999-disk-1 VolNum=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.522 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Updating DrbdRscData's flags from [] to [] (LayerRscId=10)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.523 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdRscData's flags updated from [] to [] (LayerRscId=10)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.523 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating DrbdVlmData (LayerRscId=10, VlmNr=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.523 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - DrbdVlmData created (LayerRscId=10, VlmNr=0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.524 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Creating StorageVolume LVM( rscId: 11, vlmNr:0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.524 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - StorageVolume created LVM( rscId: 11, vlmNr:0)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.524 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resources/PX2-ADMINISTRATION/VM-999-DISK-1 Key=AutoSelectedStorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.533 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resources/PX2-ADMINISTRATION/VM-999-DISK-1 Key=AutoSelectedStorPoolName Value=drbdpool)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.541 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resourcedefinitions/VM-999-DISK-1 Key=DrbdOptions/Resource/quorum Value=off)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.550 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resourcedefinitions/VM-999-DISK-1 Key=DrbdOptions/Resource/quorum Value=off)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.564 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'AutoPlaceRsc' scope 'Auto-place resource' end
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.564 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 103 'ChangedRsc' send
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.564 [grizzly-http-server-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 103 'ChangedRsc' send
Feb  5 10:20:35 px1 Satellite[1813]: 10:20:35.565 [MainWorkerPool-8] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 103 'ChangedRsc' start (seq 103)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.566 [MainWorkerPool-2] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 103 answer received (seq 347)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.566 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' start (seq 348)
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.567 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' scope 'Execute single-stage API RequestRsc' start
Feb  5 10:20:35 px1 Satellite[1813]: 10:20:35.566 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Requesting object updates from the controller
Feb  5 10:20:35 px1 Satellite[1813]: 10:20:35.567 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Requesting update for resource 'vm-999-disk-1'
Feb  5 10:20:35 px1 Satellite[1813]: 10:20:35.567 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Waiting for object updates to be received and applied
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.570 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' scope 'Execute single-stage API RequestRsc' end
Feb  5 10:20:35 px1 Controller[1801]: 10:20:35.570 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' end
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.206 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 101 answer received (seq 502)
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.206 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 101 answer received (seq 503)
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.206 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 101 complete received (seq 504)
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.207 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' start
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.207 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' end
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.342 [grizzly-http-server-5] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.342 [grizzly-http-server-5] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' start
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.342 [grizzly-http-server-5] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' end
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.342 [grizzly-http-server-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 104 'RequestThinFreeSpace' send
Feb  5 10:20:38 px1 Controller[1801]: 10:20:38.343 [grizzly-http-server-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 104 'RequestThinFreeSpace' send
Feb  5 10:20:38 px1 Satellite[1813]: 10:20:38.344 [MainWorkerPool-1] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 104 'RequestThinFreeSpace' start (seq 104)
Feb  5 10:20:38 px1 Satellite[1813]: 10:20:38.344 [MainWorkerPool-1] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 104 'RequestThinFreeSpace' scope 'Query free space' start
Feb  5 10:20:38 px1 Satellite[1813]: 10:20:38.345 [MainWorkerPool-1] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 104 'RequestThinFreeSpace' scope 'Query free space' end
Feb  5 10:20:38 px1 Satellite[1813]: 10:20:38.345 [MainWorkerPool-1] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 104 'RequestThinFreeSpace' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.262 [MainWorkerPool-2] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 349)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.263 [MainWorkerPool-2] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.263 [MainWorkerPool-2] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.263 [MainWorkerPool-2] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 350)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.264 [MainWorkerPool-2] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.264 [MainWorkerPool-2] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.264 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 351)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.264 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.265 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.265 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 352)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.265 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.266 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.272 [MainWorkerPool-7] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 353)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.272 [MainWorkerPool-7] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.273 [MainWorkerPool-7] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.274 [MainWorkerPool-8] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 354)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.274 [MainWorkerPool-8] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.274 [MainWorkerPool-8] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.366 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestPrimaryRsc' start (seq 355)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.367 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestPrimaryRsc' scope 'Execute single-stage API RequestPrimaryRsc' start
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.371 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Storing property (InstanceName=/resourcedefinitions/VM-999-DISK-1 Key=DrbdPrimarySetOn Value=PX2-ADMINISTRATION)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.382 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Property stored (InstanceName=/resourcedefinitions/VM-999-DISK-1 Key=DrbdPrimarySetOn Value=PX2-ADMINISTRATION)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.383 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Primary set for px2;  already initialized: false
Feb  5 10:20:40 px1 Satellite[1813]: 10:20:40.384 [MainWorkerPool-2] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, oneway call 'ChangedRsc' start (seq 105)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.385 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestPrimaryRsc' scope 'Execute single-stage API RequestPrimaryRsc' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.385 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestPrimaryRsc' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.385 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 356)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.386 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.386 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.440 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' start (seq 357)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.440 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' scope 'Execute single-stage API NotifyRscApplied' start
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.442 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' scope 'Execute single-stage API NotifyRscApplied' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.442 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.495 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' start (seq 358)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.496 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' scope 'Execute single-stage API UpdateFreeCapacity' start
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.496 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' scope 'Execute single-stage API UpdateFreeCapacity' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.497 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.537 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 103 answer received (seq 359)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.537 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 103 complete received (seq 360)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.538 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 104 answer received (seq 361)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.538 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 104 answer received (seq 362)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.538 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 104 complete received (seq 363)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.539 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' start (seq 364)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.539 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' scope 'Execute single-stage API RequestRsc' start
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.542 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' scope 'Execute single-stage API RequestRsc' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.542 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'RequestRsc' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.557 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 365)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.558 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'VlmDiskState(px2/vm-999-disk-1/0)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.558 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.689 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 366)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.689 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.689 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.690 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 367)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.690 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.690 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.690 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 368)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.690 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'VlmDiskState(px2/vm-999-disk-1/0)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.690 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.696 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 369)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.697 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.697 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.746 [MainWorkerPool-2] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 370)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.746 [MainWorkerPool-2] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.746 [MainWorkerPool-2] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.789 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' start (seq 371)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.789 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' scope 'Execute single-stage API NotifyRscApplied' start
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.790 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' scope 'Execute single-stage API NotifyRscApplied' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.790 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'NotifyRscApplied' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.825 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' start (seq 372)
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.825 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' scope 'Execute single-stage API UpdateFreeCapacity' start
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.826 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' scope 'Execute single-stage API UpdateFreeCapacity' end
Feb  5 10:20:40 px1 Controller[1801]: 10:20:40.826 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'UpdateFreeCapacity' end
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.219 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 102 answer received (seq 505)
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.219 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 102 answer received (seq 506)
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.219 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 102 complete received (seq 507)
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.220 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' start
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.220 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' end
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.554 [grizzly-http-server-7] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from 'RestClient(192.168.1.2; 'REST::Client/273')'
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.554 [grizzly-http-server-7] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' start
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.555 [grizzly-http-server-7] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' end
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.555 [grizzly-http-server-7] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 105 'RequestThinFreeSpace' send
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.555 [grizzly-http-server-7] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 105 'RequestThinFreeSpace' send
Feb  5 10:20:48 px1 Satellite[1813]: 10:20:48.556 [MainWorkerPool-3] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 105 'RequestThinFreeSpace' start (seq 106)
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.556 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 105 answer received (seq 373)
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.556 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 105 answer received (seq 374)
Feb  5 10:20:48 px1 Controller[1801]: 10:20:48.556 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 105 complete received (seq 375)
Feb  5 10:20:48 px1 Satellite[1813]: 10:20:48.557 [MainWorkerPool-3] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 105 'RequestThinFreeSpace' scope 'Query free space' start
Feb  5 10:20:48 px1 Satellite[1813]: 10:20:48.557 [MainWorkerPool-3] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 105 'RequestThinFreeSpace' scope 'Query free space' end
Feb  5 10:20:48 px1 Satellite[1813]: 10:20:48.557 [MainWorkerPool-3] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 105 'RequestThinFreeSpace' end
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.231 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 103 answer received (seq 508)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.232 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'RequestRsc' start (seq 509)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.232 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'RequestRsc' scope 'Execute single-stage API RequestRsc' start
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.235 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'RequestRsc' scope 'Execute single-stage API RequestRsc' end
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.235 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'RequestRsc' end
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.235 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 104 answer received (seq 510)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.235 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 104 answer received (seq 511)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.235 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 104 complete received (seq 512)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.236 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' start
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.236 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' end
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.235 [MainWorkerPool-4] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, oneway call 'ApplyRsc' start (seq 107)
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.236 [MainWorkerPool-4] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, oneway call 'ApplyRsc' scope 'Execute single-stage API ApplyRsc' start
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.238 [MainWorkerPool-4] TRACE LINSTOR/Satellite - SYSTEM - Applying update 1
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.242 [MainWorkerPool-4] INFO  LINSTOR/Satellite - SYSTEM - Resource 'vm-999-disk-1' created for node 'px1'.
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.242 [MainWorkerPool-4] INFO  LINSTOR/Satellite - SYSTEM - Resource 'vm-999-disk-1' created for node 'px2'.
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [MainWorkerPool-4] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, oneway call 'ApplyRsc' scope 'Execute single-stage API ApplyRsc' end
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - All object updates were received
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Dispatching nodes and resources to device handlers
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [MainWorkerPool-4] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, oneway call 'ApplyRsc' end
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'DrbdLayer' updating gross size of volume 'vm-999-disk-1/0' (usable: 1048576
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'StorageLayer' updating gross size of volume 'vm-999-disk-1/0' (usable: 1048840
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'StorageLayer' finished calculating sizes of volume 'vm-999-disk-1/0'. Allocated: -1, usable: 1048840
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'DrbdLayer' finished calculating sizes of volume 'vm-999-disk-1/0'. Allocated: 1048840, usable: 1048576
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.243 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'DrbdLayer' preparing 1 resources, 0 snapshots
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.244 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'DrbdLayer' finished preparing 1 resources, 0 snapshots
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.244 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'StorageLayer' preparing 1 resources, 0 snapshots
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.244 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: lvs -o lv_name,lv_path,lv_size,vg_name,pool_lv,data_percent,lv_attr --separator ; --noheadings --units k --nosuffix vg_drbd
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.378 [grizzly-http-server-8] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.378 [grizzly-http-server-8] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' start
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.378 [grizzly-http-server-8] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' end
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.378 [grizzly-http-server-8] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 106 'RequestThinFreeSpace' send
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.379 [grizzly-http-server-8] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 106 'RequestThinFreeSpace' send
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.379 [MainWorkerPool-5] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 106 'RequestThinFreeSpace' start (seq 108)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.380 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 106 answer received (seq 376)
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.380 [MainWorkerPool-5] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 106 'RequestThinFreeSpace' scope 'Query free space' start
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.380 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 106 answer received (seq 377)
Feb  5 10:20:58 px1 Controller[1801]: 10:20:58.380 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 106 complete received (seq 378)
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.397 [Thread-122] TRACE LINSTOR/Satellite - SYSTEM -   vm-100102-disk-1_00000;/dev/vg_drbd/vm-100102-disk-1_00000;954425344.00;vg_drbd;;;-wi-ao----
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.397 [Thread-122] TRACE LINSTOR/Satellite - SYSTEM -   vm-100104-disk-1_00000;/dev/vg_drbd/vm-100104-disk-1_00000;33562624.00;vg_drbd;;;-wi-ao----
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.397 [Thread-122] TRACE LINSTOR/Satellite - SYSTEM -   vm-100106-disk-1_00000;/dev/vg_drbd/vm-100106-disk-1_00000;33562624.00;vg_drbd;;;-wi-ao----
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.398 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 153ms: lvs -o lv_name,lv_path,lv_size,vg_name,pool_lv,data_percent,lv_attr --separator ; --noheadings --units k --nosuffix vg_drbd
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.398 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: vgs -o vg_name,vg_extent_size --separator ; --units k --noheadings --nosuffix vg_drbd
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.416 [Thread-124] TRACE LINSTOR/Satellite - SYSTEM -   vg_drbd;4096.00
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.416 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 17ms: vgs -o vg_name,vg_extent_size --separator ; --units k --noheadings --nosuffix vg_drbd
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.417 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'StorageLayer' finished preparing 1 resources, 0 snapshots
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.417 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'DrbdLayer' processing resource 'vm-999-disk-1'
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.417 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Synchronizing Linstor-state with DRBD-state for resource vm-999-disk-1
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.417 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'StorageLayer' processing resource 'vm-999-disk-1'
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.418 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Lv vm-999-disk-1_00000 will be created
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.418 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: lvcreate --size 1048840k -n vg_drbd/vm-999-disk-1_00000 -y --type=linear
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.435 [Thread-126] TRACE LINSTOR/Satellite - SYSTEM -   Rounding up size to full physical extent 1.00 GiB
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.618 [Thread-126] TRACE LINSTOR/Satellite - SYSTEM -   Logical volume "vm-999-disk-1_00000" created.
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.620 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 201ms: lvcreate --size 1048840k -n vg_drbd/vm-999-disk-1_00000 -y --type=linear
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.625 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Waiting until device [/dev/vg_drbd/vm-999-disk-1_00000] appears (up to 500ms)
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.625 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Device [/dev/vg_drbd/vm-999-disk-1_00000] appeared after 4ms
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.626 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: blockdev --getsize64 /dev/vg_drbd/vm-999-disk-1_00000
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.635 [Thread-129] TRACE LINSTOR/Satellite - SYSTEM - 1077936128
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.635 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 1ms: blockdev --getsize64 /dev/vg_drbd/vm-999-disk-1_00000
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.647 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: wipefs -a -f /dev/vg_drbd/vm-999-disk-1_00000
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.653 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 5ms: wipefs -a -f /dev/vg_drbd/vm-999-disk-1_00000
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.654 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'StorageLayer' finished processing resource 'vm-999-disk-1'
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.656 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: drbdadm --config-to-test /var/lib/linstor.d/vm-999-disk-1.res_tmp --config-to-exclude /var/lib/linstor.d/vm-999-disk-1.res sh-nop
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.659 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 2ms: drbdadm --config-to-test /var/lib/linstor.d/vm-999-disk-1.res_tmp --config-to-exclude /var/lib/linstor.d/vm-999-disk-1.res sh-nop
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.659 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: drbdadm -vvv --max-peers 7 -- --force create-md vm-999-disk-1/0
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.664 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - drbdmeta 1000 v09 /dev/vg_drbd/vm-999-disk-1_00000 internal create-md 7 --force
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.674 [Thread-136] TRACE LINSTOR/Satellite - SYSTEM -
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.674 [Thread-136] TRACE LINSTOR/Satellite - SYSTEM - Do you want to proceed?
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.674 [Thread-136] TRACE LINSTOR/Satellite - SYSTEM - *** confirmation forced via --force option ***
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.674 [Thread-136] TRACE LINSTOR/Satellite - SYSTEM - initializing bitmap (228 KB) to all zero
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - md_offset 1077932032
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - al_offset 1077899264
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - bm_offset 1077665792
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM -
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - Found some data
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM -
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM -  ==> This might destroy existing data! <==
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - initializing activity log
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - Writing meta data...
Feb  5 10:20:58 px1 Satellite[1813]: 10:20:58.675 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - New drbd meta data block successfully created.
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.705 [Thread-135] TRACE LINSTOR/Satellite - SYSTEM - drbdmeta 1000 v09 /dev/vg_drbd/vm-999-disk-1_00000 internal write-dev-uuid C1760046A384529E
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.709 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 3049ms: drbdadm -vvv --max-peers 7 -- --force create-md vm-999-disk-1/0
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.711 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: drbdadm -vvv adjust vm-999-disk-1
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.715 [Thread-138] TRACE LINSTOR/Satellite - SYSTEM - New resource vm-999-disk-1
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.715 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdsetup new-resource vm-999-disk-1 0 --quorum=off
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.715 [Thread-138] TRACE LINSTOR/Satellite - SYSTEM - New minor 1000 (vol:0)
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.716 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': create resource name:vm-999-disk-1 role:Secondary suspended:no
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.716 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdsetup new-minor vm-999-disk-1 1000 0
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.718 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': create device name:vm-999-disk-1 volume:0 minor:1000 disk:Diskless client:no quorum:yes
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.718 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdsetup new-peer vm-999-disk-1 1 --_name=px2 --allow-two-primaries=yes --shared-secret=v3pJ3D6BQpKZRkrW1Var --cram-hmac-alg=sha1
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.720 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': create connection name:vm-999-disk-1 peer-node-id:1 conn-name:px2 connection:StandAlone role:Unknown
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.720 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': create peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 replication:Off peer-disk:DUnknown peer-client:no resync-suspended:no
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.721 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdsetup new-path vm-999-disk-1 1 ipv4:192.168.1.1:7000 ipv4:192.168.1.2:7000
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.723 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdmeta 1000 v09 /dev/vg_drbd/vm-999-disk-1_00000 internal apply-al
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.723 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': create path name:vm-999-disk-1 peer-node-id:1 conn-name:px2 local:ipv4:192.168.1.1:7000 peer:ipv4:192.168.1.2:7000
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.727 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdsetup attach 1000 /dev/vg_drbd/vm-999-disk-1_00000 /dev/vg_drbd/vm-999-disk-1_00000 internal --discard-zeroes-if-aligned=yes --rs-discard-granularity=8192
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.728 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change device name:vm-999-disk-1 volume:0 minor:1000 disk:Attaching client:no quorum:yes
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.729 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change device name:vm-999-disk-1 volume:0 minor:1000 disk:Inconsistent client:no quorum:yes
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.730 [Thread-137] TRACE LINSTOR/Satellite - SYSTEM - drbdsetup connect vm-999-disk-1 1
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.732 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change connection name:vm-999-disk-1 peer-node-id:1 conn-name:px2 connection:Unconnected
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.732 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change connection name:vm-999-disk-1 peer-node-id:1 conn-name:px2 connection:Connecting
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.733 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 21ms: drbdadm -vvv adjust vm-999-disk-1
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.734 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Layer 'DrbdLayer' finished processing resource 'vm-999-disk-1'
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.735 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: stat -L -c %t:%T /dev/vg_drbd/vm-999-disk-1_00000
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.737 [Thread-139] TRACE LINSTOR/Satellite - SYSTEM - fd:3
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.737 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 1ms: stat -L -c %t:%T /dev/vg_drbd/vm-999-disk-1_00000
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.737 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - SysFs: '/sys/fs/cgroup/blkio/blkio.throttle.read_bps_device' for 253:3 already has expected value of null
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.738 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - SysFs: '/sys/fs/cgroup/blkio/blkio.throttle.write_bps_device' for 253:3 already has expected value of null
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.738 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: vgs -o vg_name,vg_size --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.781 [Thread-141] TRACE LINSTOR/Satellite - SYSTEM -   vg_drbd;4877922304.00
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.782 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 43ms: vgs -o vg_name,vg_size --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.782 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: vgs -o vg_name,vg_free --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.799 [Thread-143] TRACE LINSTOR/Satellite - SYSTEM -   vg_drbd;3855319040.00
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.800 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 16ms: vgs -o vg_name,vg_free --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.801 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: vgs -o vg_name,vg_size --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.817 [Thread-145] TRACE LINSTOR/Satellite - SYSTEM -   vg_drbd;4877922304.00
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.818 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 16ms: vgs -o vg_name,vg_size --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.818 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: vgs -o vg_name,vg_free --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.835 [Thread-147] TRACE LINSTOR/Satellite - SYSTEM -   vg_drbd;3855319040.00
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.836 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 17ms: vgs -o vg_name,vg_free --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.836 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Executing command: vgs -o vg_name,vg_free --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.853 [Thread-149] TRACE LINSTOR/Satellite - SYSTEM -   vg_drbd;3855319040.00
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.854 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - External command finished in 17ms: vgs -o vg_name,vg_free --units k --separator ; --noheadings --nosuffix vg_drbd
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.854 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Waiting for queued resource handlers to finish
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.854 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - All dispatched resource handlers finished
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.854 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Waiting for queued node handlers to finish
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.854 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - All dispatched node handlers finished
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.855 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - End DeviceManager cycle 5
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.855 [DeviceManager] DEBUG LINSTOR/Satellite - SYSTEM - Begin DeviceManager cycle 6
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.855 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Collecting update notifications
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.855 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Requesting object updates from the controller
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.855 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Requesting update for resource 'vm-999-disk-1'
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.855 [MainWorkerPool-5] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 106 'RequestThinFreeSpace' scope 'Query free space' end
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.856 [MainWorkerPool-5] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 106 'RequestThinFreeSpace' end
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.856 [MainWorkerPool-2] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 103 'ChangedRsc' end
Feb  5 10:21:01 px1 Satellite[1813]: 10:21:01.858 [DeviceManager] TRACE LINSTOR/Satellite - SYSTEM - Waiting for object updates to be received and applied
Feb  5 10:21:02 px1 Satellite[1813]: 10:21:02.249 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change path name:vm-999-disk-1 peer-node-id:1 conn-name:px2 local:ipv4:192.168.1.1:7000 peer:ipv4:192.168.1.2:7000 established:yes
Feb  5 10:21:02 px1 Satellite[1813]: 10:21:02.288 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change connection name:vm-999-disk-1 peer-node-id:1 conn-name:px2 connection:Connected role:Secondary
Feb  5 10:21:02 px1 Satellite[1813]: 10:21:02.306 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 replication:WFBitMapT peer-disk:UpToDate peer-client:no
Feb  5 10:21:02 px1 Satellite[1813]: 10:21:02.312 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': call helper name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 minor:1000 helper:before-resync-target
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.313 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 379)
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.313 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.313 [MainWorkerPool-3] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.314 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 380)
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.314 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.314 [MainWorkerPool-5] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:21:02 px1 Satellite[1813]: 10:21:02.314 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': response helper name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 minor:1000 helper:before-resync-target status:0
Feb  5 10:21:02 px1 Satellite[1813]: 10:21:02.314 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 replication:SyncTarget done:0.00
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.315 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 381)
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.315 [MainWorkerPool-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:21:02 px1 Controller[1801]: 10:21:02.315 [MainWorkerPool-6] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:21:05 px1 Satellite[1813]: 10:21:05.313 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 done:28.35
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.247 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 105 answer received (seq 513)
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.247 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 105 answer received (seq 514)
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.247 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 105 complete received (seq 515)
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.248 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' start
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.248 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' end
Feb  5 10:21:08 px1 Satellite[1813]: 10:21:08.313 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 done:55.33
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.387 [grizzly-http-server-9] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from 'RestClient(192.168.1.2; 'REST::Client/273')'
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.387 [grizzly-http-server-9] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' start
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.387 [grizzly-http-server-9] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.2; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' end
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.388 [grizzly-http-server-9] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 107 'RequestThinFreeSpace' send
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.388 [grizzly-http-server-9] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 107 'RequestThinFreeSpace' send
Feb  5 10:21:08 px1 Satellite[1813]: 10:21:08.388 [MainWorkerPool-6] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 107 'RequestThinFreeSpace' start (seq 109)
Feb  5 10:21:08 px1 Satellite[1813]: 10:21:08.389 [MainWorkerPool-6] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 107 'RequestThinFreeSpace' scope 'Query free space' start
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.389 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 107 answer received (seq 382)
Feb  5 10:21:08 px1 Satellite[1813]: 10:21:08.390 [MainWorkerPool-6] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 107 'RequestThinFreeSpace' scope 'Query free space' end
Feb  5 10:21:08 px1 Satellite[1813]: 10:21:08.390 [MainWorkerPool-6] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 107 'RequestThinFreeSpace' end
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.390 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 107 answer received (seq 383)
Feb  5 10:21:08 px1 Controller[1801]: 10:21:08.390 [MainWorkerPool-5] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 107 complete received (seq 384)
Feb  5 10:21:11 px1 Satellite[1813]: 10:21:11.385 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 done:75.58
Feb  5 10:21:14 px1 Satellite[1813]: 10:21:14.083 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': call helper name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 minor:1000 helper:after-resync-target
Feb  5 10:21:14 px1 Satellite[1813]: 10:21:14.085 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': response helper name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 minor:1000 helper:after-resync-target status:0
Feb  5 10:21:14 px1 Satellite[1813]: 10:21:14.085 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change device name:vm-999-disk-1 volume:0 minor:1000 disk:UpToDate client:no quorum:yes
Feb  5 10:21:14 px1 Satellite[1813]: 10:21:14.086 [DrbdEventService] TRACE LINSTOR/Satellite - SYSTEM - DRBD 'events2': change peer-device name:vm-999-disk-1 peer-node-id:1 conn-name:px2 volume:0 replication:Established
Feb  5 10:21:14 px1 Controller[1801]: 10:21:14.086 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 385)
Feb  5 10:21:14 px1 Controller[1801]: 10:21:14.087 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:21:14 px1 Controller[1801]: 10:21:14.087 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:21:14 px1 Controller[1801]: 10:21:14.087 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' start (seq 386)
Feb  5 10:21:14 px1 Controller[1801]: 10:21:14.087 [MainWorkerPool-1] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', event 'ResourceState(px2/vm-999-disk-1)' Value
Feb  5 10:21:14 px1 Controller[1801]: 10:21:14.088 [MainWorkerPool-1] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px2', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.263 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' start (seq 516)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.263 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', event 'ResourceState(px1/vm-999-disk-1)' Value
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' start (seq 517)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', event 'ResourceState(px1/vm-999-disk-1)' Value
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' start (seq 518)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', event 'ResourceState(px1/vm-999-disk-1)' Value
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.264 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' start (seq 519)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', event 'ResourceState(px1/vm-999-disk-1)' Value
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' start (seq 520)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', event 'ResourceState(px1/vm-999-disk-1)' Value
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' start (seq 521)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', event 'ResourceState(px1/vm-999-disk-1)' Value
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'Event' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.265 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'NotifyRscApplied' start (seq 522)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.266 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'NotifyRscApplied' scope 'Execute single-stage API NotifyRscApplied' start
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.267 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'NotifyRscApplied' scope 'Execute single-stage API NotifyRscApplied' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.267 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'NotifyRscApplied' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.267 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'UpdateFreeCapacity' start (seq 523)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.267 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'UpdateFreeCapacity' scope 'Execute single-stage API UpdateFreeCapacity' start
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.268 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'UpdateFreeCapacity' scope 'Execute single-stage API UpdateFreeCapacity' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.268 [MainWorkerPool-4] DEBUG LINSTOR/Controller - SYSTEM - Peer Node: 'px1', oneway call 'UpdateFreeCapacity' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.268 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 103 answer received (seq 524)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.268 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 103 complete received (seq 525)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.286 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 106 answer received (seq 526)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.286 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 106 answer received (seq 527)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.286 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 106 complete received (seq 528)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.288 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' start
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.288 [MainWorkerPool-4] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Assemble storage pool list' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.465 [grizzly-http-server-6] DEBUG LINSTOR/Controller - SYSTEM - REST access api 'LstStorPool' from 'RestClient(192.168.1.1; 'REST::Client/273')'
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.465 [grizzly-http-server-6] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' start
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.466 [grizzly-http-server-6] TRACE LINSTOR/Controller - SYSTEM - Peer RestClient(192.168.1.1; 'REST::Client/273'), Background operation 'LstStorPool' scope 'Fetch thin capacity info' end
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.466 [grizzly-http-server-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px1', API call 108 'RequestThinFreeSpace' send
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.466 [grizzly-http-server-6] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 108 'RequestThinFreeSpace' send
Feb  5 10:21:18 px1 Satellite[1813]: 10:21:18.467 [MainWorkerPool-7] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 108 'RequestThinFreeSpace' start (seq 110)
Feb  5 10:21:18 px1 Satellite[1813]: 10:21:18.467 [MainWorkerPool-7] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 108 'RequestThinFreeSpace' scope 'Query free space' start
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.468 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 108 answer received (seq 387)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.468 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 108 answer received (seq 388)
Feb  5 10:21:18 px1 Controller[1801]: 10:21:18.468 [MainWorkerPool-3] TRACE LINSTOR/Controller - SYSTEM - Peer Node: 'px2', API call 108 complete received (seq 389)
Feb  5 10:21:18 px1 Satellite[1813]: 10:21:18.468 [MainWorkerPool-7] TRACE LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 108 'RequestThinFreeSpace' scope 'Query free space' end
Feb  5 10:21:18 px1 Satellite[1813]: 10:21:18.468 [MainWorkerPool-7] DEBUG LINSTOR/Satellite - SYSTEM - Peer 192.168.1.1:52122, API call 108 'RequestThinFreeSpace' end
Feb  5 10:21:23 px1 pvedaemon[5275]: VM 999 creating disks failed
Feb  5 10:21:23 px1 pvedaemon[5275]: unable to create VM 999 - error with cfs lock 'storage-drbdstorage': Could not autoplace resource vm-999-disk-1, because: [{"ret_code":20185089,"message":"Resource 'vm-999-disk-1' successfully autoplaced on 2 nodes","details":"Used storage pool: 'drbdpool'\nUsed nodes: 'px1', 'px2'","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":-9223372036834589707,"message":"Could not find suitable node to automatically create a tie breaking resource for 'vm-999-disk-1'.","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":20185091,"message":"Created resource 'vm-999-disk-1' on 'px2'","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":20185091,"message":"Created resource 'vm-999-disk-1' on 'px1'","obj_refs":{"RscDfn":"vm-999-disk-1"}},{"ret_code":-4611686018407201818,"message":"Deployed resource did not appear","details":"Auto-placing resource: vm-999-disk-1","obj_refs":{"RscDfn":"vm-999-disk-1"}}]  at /usr/share/perl5/PVE/Storage/Custom/LINSTORPlugin.pm line 285. #011PVE::Storage::Custom::LINSTORPlugin::alloc_image("PVE::Storage::Custom::LINSTORPlugin", "drbdstorage", HASH(0x559e92395550), 999, "raw", undef, 1048576) called at /usr/share/perl5/PVE/Storage.pm line 738 #011eval {...} called at /usr/share/perl5/PVE/Storage.pm line 738 #011PVE::Storage::__ANON__() called at /usr/share/perl5/PVE/Cluster.pm line 915 #011eval {...} called at /usr/share/perl5/PVE/Cluster.pm line 883 #011PVE::Cluster::__ANON__("storage-drbdstorage", undef, CODE(0x559e8bd58ba8)) called at /usr/share/perl5/PVE/Cluster.pm line 954 #011PVE::Cluster::cfs_lock_storage("drbdstorage", undef, CODE(0x559e8bd58ba8)) called at /usr/share/perl5/PVE/Storage/Plugin.pm line 390 #011PVE::Storage::Plugin::cluster_lock_storage("PVE::Storage::Custom::LINSTORPlugin", "drbdstorage", 1, undef, CODE(0x559e8bd58ba8)) called at /usr/share/perl5/PVE/Storage.pm line 743 #011PVE::Storage::vdisk_alloc(HASH(0x559e923fd868), "drbdstorage", 999, "raw", undef, 1048576) called at /usr/share/perl5/PVE/API2/Qemu.pm line 181 #011PVE::API2::Qemu::__ANON__("scsi0", HASH(0x559e8bd589e0)) called at /usr/share/perl5/PVE/QemuServer.pm line 3288 #011PVE::QemuServer::foreach_drive(HASH(0x559e923b5d00), CODE(0x559e8bd711c0)) called at /usr/share/perl5/PVE/API2/Qemu.pm line 216 #011eval {...} called at /usr/share/perl5/PVE/API2/Qemu.pm line 216 #011PVE::API2::Qemu::__ANON__(PVE::RPCEnvironment=HASH(0x559e92364a50), "root\@pam", HASH(0x559e923b5d00), "x86_64", HASH(0x559e923fd868), 999, undef, HASH(0x559e923b5d00), ...) called at /usr/share/perl5/PVE/API2/Qemu.pm line 604 #011eval {...} called at /usr/share/perl5/PVE/API2/Qemu.pm line 602 #011PVE::API2::Qemu::__ANON__() called at /usr/share/perl5/PVE/Tools.pm line 203 #011eval {...} called at /usr/share/perl5/PVE/Tools.pm line 203 #011PVE::Tools::lock_file_full("/var/lock/qemu-server/lock-999.conf", 1, 0, CODE(0x559e8bd58410)) called at /usr/share/perl5/PVE/Tools.pm line 212 #011PVE::Tools::lock_file("/var/lock/qemu-server/lock-999.conf", 1, CODE(0x559e8bd58410)) called at /usr/share/perl5/PVE/AbstractConfig.pm line 78 #011PVE::AbstractConfig::lock_config_full("PVE::QemuConfig", 999, 1, CODE(0x559e8bd58410)) called at /usr/share/perl5/PVE/API2/Qemu.pm line 636 #011PVE::API2::Qemu::__ANON__() called at /usr/share/perl5/PVE/API2/Qemu.pm line 659 #011eval {...} called at /usr/share/perl5/PVE/API2/Qemu.pm line 659 #011PVE::API2::Qemu::__ANON__("UPID:px1:0000149B:0001379F:5E3A88E3:qmcreate:9"...) called at /usr/share/perl5/PVE/RESTEnvironment.pm line 610 #011eval {...} called at /usr/share/perl5/PVE/RESTEnvironment.pm line 601 #011PVE::RESTEnvironment::fork_worker(PVE::RPCEnvironment=HASH(0x559e92364a50), "qmcreate", 999, "root\@pam", CODE(0x559e923f6438)) called at /usr/share/perl5/PVE/API2/Qemu.pm line 671 #011PVE::API2::Qemu::__ANON__(HASH(0x559e923b5d00)) called at /usr/share/perl5/PVE/RESTHandler.pm line 446 #011PVE::RESTHandler::handle("PVE::API2::Qemu", HASH(0x559e9058be20), HASH(0x559e923b5d00)) called at /usr/share/perl5/PVE/HTTPServer.pm line 167 #011eval {...} called at /usr/share/perl5/PVE/HTTPServer.pm line 133 #011PVE::HTTPServer::rest_handler(PVE::HTTPServer=HASH(0x559e8bd58380), "10.31.39.193", "POST", "/nodes/px1/qemu", HASH(0x559e923c73d8), HASH(0x559e92364d20), "extjs") called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 712 #011eval {...} called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 686 #011PVE::APIServer::AnyEvent::handle_api2_request(PVE::HTTPServer=HASH(0x559e8bd58380), HASH(0x559e923f6540), HASH(0x559e923c73d8), "POST", "/api2/extjs/nodes/px1/qemu") called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 939 #011eval {...} called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 931 #011PVE::APIServer::AnyEvent::handle_request(PVE::HTTPServer=HASH(0x559e8bd58380), HASH(0x559e923f6540), HASH(0x559e923c73d8), "POST", "/api2/extjs/nodes/px1/qemu") called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 1325 #011PVE::APIServer::AnyEvent::__ANON__(AnyEvent::Handle=HASH(0x559e91b28c40), "scsi0=drbdstorage%3A1\x{26}cores=1\x{26}ide2=none%2Cmedia%3Dcdrom\x{26}socke"...) called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Handle.pm line 1522 #011AnyEvent::Handle::__ANON__(AnyEvent::Handle=HASH(0x559e91b28c40)) called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Handle.pm line 1332 #011AnyEvent::Handle::_drain_rbuf(AnyEvent::Handle=HASH(0x559e91b28c40)) called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Handle.pm line 2032 #011AnyEvent::Handle::__ANON__(EV::IO=SCALAR(0x559e92395bf8), 1) called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Impl/EV.pm line 88 #011eval {...} called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent/Impl/EV.pm line 88 #011AnyEvent::CondVar::Base::_wait(AnyEvent::CondVar=HASH(0x559e91b28688)) called at /usr/lib/x86_64-linux-gnu/perl5/5.24/AnyEvent.pm line 2026 #011AnyEvent::CondVar::Base::recv(AnyEvent::CondVar=HASH(0x559e91b28688)) called at /usr/share/perl5/PVE/APIServer/AnyEvent.pm line 1612 #011PVE::APIServer::AnyEvent::run(PVE::HTTPServer=HASH(0x559e8bd58380)) called at /usr/share/perl5/PVE/Service/pvedaemon.pm line 52 #011PVE::Service::pvedaemon::run(PVE::Service::pvedaemon=HASH(0x559e919c67e8)) called at /usr/share/perl5/PVE/Daemon.pm line 171 #011eval {...} called at /usr/share/perl5/PVE/Daemon.pm line 171 #011PVE::Daemon::__ANON__(PVE::Service::pvedaemon=HASH(0x559e919c67e8)) called at /usr/share/perl5/PVE/Daemon.pm line 391 #011eval {...} called at /usr/share/perl5/PVE/Daemon.pm line 380 #011PVE::Daemon::__ANON__(PVE::Service::pvedaemon=HASH(0x559e919c67e8), undef) called at /usr/share/perl5/PVE/Daemon.pm line 552 #011eval {...} called at /usr/share/perl5/PVE/Daemon.pm line 550 #011PVE::Daemon::start(PVE::Service::pvedaemon=HASH(0x559e919c67e8), undef) called at /usr/share/perl5/PVE/Daemon.pm line 661 #011PVE::Daemon::__ANON__(HASH(0x559e8bd51410)) called at /usr/share/perl5/PVE/RESTHandler.pm line 446 #011PVE::RESTHandler::handle("PVE::Service::pvedaemon", HASH(0x559e919c6b00), HASH(0x559e8bd51410)) called at /usr/share/perl5/PVE/RESTHandler.pm line 855 #011eval {...} called at /usr/share/perl5/PVE/RESTHandler.pm line 838 #011PVE::RESTHandler::cli_handler("PVE::Service::pvedaemon", "pvedaemon start", "start", ARRAY(0x559e8c0101e8), ARRAY(0x559e8bd70710), undef, undef, undef) called at /usr/share/perl5/PVE/CLIHandler.pm line 580 #011PVE::CLIHandler::__ANON__(ARRAY(0x559e8bd51638), CODE(0x559e8bfd0f08), undef) called at /usr/share/perl5/PVE/CLIHandler.pm line 657 #011PVE::CLIHandler::run_cli_handler("PVE::Service::pvedaemon", "prepare", CODE(0x559e8bfd0f08)) called at /usr/bin/pvedaemon line 27