search

openlvc / portico

Portico is an open source, cross-platform, fully supported HLA RTI implementation. Designed with modularity and flexibility in mind, Portico is a production-grade RTI for the Simulation and Training Community, so come say hi!
http://www.porticoproject.org
151 stars 81 forks source link

Race condition when time regulation requested while other federates are joining #252

Open tpr1 opened 6 years ago

tpr1 commented 6 years ago

This happens in Portico 2.1.0:

A request to enable time regulation that occurs after sending a RoleCall to a new federate, but before that new federate finishes joining the federation, will leave the federation in an inconsistent state.

So when this happens:

DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf, federation=TestFederation, source=f4b579c4-5c40-4a8a-8a07-94191fcf1e88
INFO  [Regular] portico.lrc.jgroups: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] joined federation [TestFederation]
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:3,name:TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] by local federate [GLDFederate]
DEBUG [main] portico.lrc: @REMOTE Federate [GLDFederate] requests ENABLE time regulation (fedtime=0.0, lookahead=0.1)
DEBUG [main] portico.lrc: ENABLED time regulating for [GLDFederate] (fedtime=0.0)

Time advancement breaks:

DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [3.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @4.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @4.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [4.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [4.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097153] with attributes [548, 549, 550] @2.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097154] with attributes [548, 549, 550] @2.1
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [4.0]
DEBUG [Thread-1] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [3.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097155] with attributes [546] @2.1
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [3.0]

There are two weird things in this log.

  1. This federate (TestFederate) receives a TSO message with timestamp 2.1 during its logical time 4 when this message should have been received at its logical time 3
  2. This federate (TestFederate) was granted logical time 4 before a time regulating federate (GLDFederate) made the request for time 3.

I assume that TestFederate never receives the time regulation request because it is in a partial-join state when GLDFederate makes the request.

The complete log for GLDFederate:

DEBUG [main] portico.lrc: Creating new LRC
DEBUG [main] portico.lrc: Portico version: 2.1.0 (build 3)
DEBUG [main] portico.lrc: Interface: HLA13
DEBUG [main] portico.lrc: Messaging framework configuration complete
INFO  [main] portico.lrc: LRC initialized (HLA version: HLA13)
INFO  [main] portico.lrc: Opening LRC Connection
INFO  [main] portico.lrc.jgroups: jgroups connection is up and running
DEBUG [main] portico.lrc: ATTEMPT Join federate [GLDFederate] to federation [TestFederation]

-------------------------------------------------------------------
GMS: address=vagrant-38664, cluster=TestFederation, physical address=127.0.0.1:52816
-------------------------------------------------------------------
DEBUG [main] portico.lrc.jgroups: SUCCESS Connected to channel [TestFederation]
DEBUG [Regular] portico.lrc.jgroups: (GMS) findCoordinator(vagrant-38664)
DEBUG [Regular] portico.lrc.jgroups: (GMS) setManifest(vagrant-34351)
DEBUG [Regular] portico.lrc.jgroups: Received updated manifest from 518a6613-4b3e-455d-919a-fa89451ded0f
DEBUG [Regular] portico.lrc.jgroups: Installed new manifest (follows)
DEBUG [Regular] portico.lrc.jgroups: 
-----------------------------------
Manifest: channel=TestFederation
-----------------------------------
 Version        = 4
 Local UUID     = dc314b95-14b2-4f3e-b4b8-3514c9535052
 Highest Handle = 2
 Is Federation  = true
 Channel members: 2
  (application) id=2, uuid=dc314b95-14b2-4f3e-b4b8-3514c9535052
     (federate) id=1, name=FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0, uuid=518a6613-4b3e-455d-919a-fa89451ded0f **CO-ORDINATOR**

DEBUG [Regular] portico.lrc.jgroups: (GMS) findCoordinator(vagrant-41004)
DEBUG [Regular] portico.lrc.jgroups: (GMS) setManifest(vagrant-34351)
DEBUG [Regular] portico.lrc.jgroups: Received updated manifest from 518a6613-4b3e-455d-919a-fa89451ded0f
DEBUG [Regular] portico.lrc.jgroups: Installed new manifest (follows)
DEBUG [Regular] portico.lrc.jgroups: 
-----------------------------------
Manifest: channel=TestFederation
-----------------------------------
 Version        = 5
 Local UUID     = dc314b95-14b2-4f3e-b4b8-3514c9535052
 Highest Handle = 3
 Is Federation  = true
 Channel members: 3
  (application) id=3, uuid=f4b579c4-5c40-4a8a-8a07-94191fcf1e88
  (application) id=2, uuid=dc314b95-14b2-4f3e-b4b8-3514c9535052
     (federate) id=1, name=FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0, uuid=518a6613-4b3e-455d-919a-fa89451ded0f **CO-ORDINATOR**

DEBUG [main] portico.lrc.jgroups: Validate that [0] modules can merge successfully with the existing FOM
DEBUG [main] portico.lrc.jgroups: Modules can be merged successfully, continue with join
DEBUG [main] portico.lrc.jgroups: REQUEST joinFederation: federate=GLDFederate, federation=TestFederation
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(vagrant-38664)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=GLDFederate, federation=TestFederation, source=dc314b95-14b2-4f3e-b4b8-3514c9535052
INFO  [Regular] portico.lrc.jgroups: Federate [GLDFederate] joined federation [TestFederation]
INFO  [main] portico.lrc.jgroups: SUCCESS Joined federation with name=GLDFederate
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:1,name:FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] by local federate [GLDFederate]
DEBUG [Regular] portico.lrc: @REMOTE Synchronization point [readyToResign] ANNOUNCED by [null]
INFO  [Regular] portico.lrc: Synchronization point [readyToResign] ANNOUNCED by [null] to [GLDFederate]
INFO  [main] portico.lrc: SUCCESS Joined federate [GLDFederate] to federation [TestFederation]: handle=2
DEBUG [main] portico.lrc: REQUEST Enable asynchronous delivery for [GLDFederate]
DEBUG [main] portico.lrc: SUCCESS Enabled asynchronous delivery for [GLDFederate]
DEBUG [main] portico.lrc: REQUEST Enable time constrained for [GLDFederate]
INFO  [main] portico.lrc: PENDING Enable time constrained PENDING for [GLDFederate]
DEBUG [Regular] portico.lrc: @REMOTE Synchronization point [readyToPopulate] ANNOUNCED by [null]
INFO  [Regular] portico.lrc: Synchronization point [readyToPopulate] ANNOUNCED by [null] to [GLDFederate]
DEBUG [Regular] portico.lrc: @REMOTE Synchronization point [readyToRun] ANNOUNCED by [null]
INFO  [Regular] portico.lrc: Synchronization point [readyToRun] ANNOUNCED by [null] to [GLDFederate]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=2097151
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=1
DEBUG [main] portico.lrc: @REMOTE Federate [GLDFederate] requests ENABLE time constrained
INFO  [main] portico.lrc: ENABLED time constrained for [GLDFederate]
DEBUG [main] portico.lrc: REQUEST Enable time regulation for [GLDFederate]: fedtime=0.0, lookahead=0.1
INFO  [main] portico.lrc: PENDING Enable time regulation PENDING for [GLDFederate]
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(vagrant-41004)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf, federation=TestFederation, source=f4b579c4-5c40-4a8a-8a07-94191fcf1e88
INFO  [Regular] portico.lrc.jgroups: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] joined federation [TestFederation]
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:3,name:TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] by local federate [GLDFederate]
DEBUG [main] portico.lrc: @REMOTE Federate [GLDFederate] requests ENABLE time regulation (fedtime=0.0, lookahead=0.1)
DEBUG [main] portico.lrc: ENABLED time regulating for [GLDFederate] (fedtime=0.0)
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=4194302
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] subscribed to interaction class [782]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] published interaction class [716]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] published interaction class [724]
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [716] with parameters [707, 708, 709, 710, 717, 718, 719] (RO)
DEBUG [main] portico.lrc: DISCARD interaction of class [716]: no subscription
DEBUG [main] portico.lrc: (veto) Interaction ignored: not subscribed
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ENABLE time constrained
INFO  [main] portico.lrc: ENABLED time constrained for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ENABLE time regulation (fedtime=0.0, lookahead=0.1)
DEBUG [main] portico.lrc: ENABLED time regulating for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] (fedtime=0.0)
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [724]
INFO  [main] portico.lrc: SUCCESS Published interaction class [724]
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [716]
INFO  [main] portico.lrc: SUCCESS Published interaction class [716]
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [813]
INFO  [main] portico.lrc: SUCCESS Published interaction class [813]
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [819]
INFO  [main] portico.lrc: SUCCESS Published interaction class [819]
DEBUG [main] portico.lrc: ATTEMPT Subscribe to interaction class [806]
INFO  [main] portico.lrc: SUCCESS Subscribed to interaction class [806]
DEBUG [main] portico.lrc: ATTEMPT Subscribe to interaction class [782]
INFO  [main] portico.lrc: SUCCESS Subscribed to interaction class [782]
DEBUG [main] portico.lrc: ATTEMPT Subscribe to interaction class [797]
INFO  [main] portico.lrc: SUCCESS Subscribed to interaction class [797]
DEBUG [main] portico.lrc: ATTEMPT Publish [547] with attributes [548, 549, 550, 551]
INFO  [main] portico.lrc: SUCCESS Published [547] with attributes [548, 549, 550, 502, 551]
DEBUG [main] portico.lrc: ATTEMPT Publish [545] with attributes [546]
INFO  [main] portico.lrc: SUCCESS Published [545] with attributes [546, 502]
DEBUG [main] portico.lrc: ATTEMPT Subscribe to [542] with attributes [544, 543]
INFO  [main] portico.lrc: SUCCESS Subscribeed to [542] with attributes [544, 543]
DEBUG [main] portico.lrc: ATTEMPT Send interaction [716] with parameters [720, 721, 722, 723, 717, 718, 719] (RO)
INFO  [main] portico.lrc: SUCCESS Sent interaction [716] with parameters [720, 721, 722, 723, 717, 718, 719] (RO)
INFO  [main] portico.lrc: NOTICE  Federate [GLDFederate] achieved sync point [readyToPopulate]
DEBUG [main] portico.lrc: @REMOTE Federate [GLDFederate] ACHIEVED synchronization point [readyToPopulate]
DEBUG [main] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToPopulate]
DEBUG [main] portico.lrc: @REMOTE Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] ACHIEVED synchronization point [readyToPopulate]
DEBUG [main] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToPopulate]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] published interaction class [797]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] published interaction class [806]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] subscribed to interaction class [813]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] subscribed to interaction class [819]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] published object class [542] with attributes [544, 502, 543]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] subscribed to object class [545] with attributes [546]]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] subscribed to object class [547] with attributes [548, 549, 550, 551]]
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] ACHIEVED synchronization point [readyToPopulate]
INFO  [main] portico.lrc: Federation SYNCHRONIZED on point [readyToPopulate], queued callback
DEBUG [main] portico.lrc: ATTEMPT Register instance of class [547] , name=null
INFO  [main] portico.lrc: SUCCESS Register instance of class [547], object handle=2097153
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [551] (RO)
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [551] (RO)
DEBUG [main] portico.lrc: ATTEMPT Register instance of class [547] , name=null
INFO  [main] portico.lrc: SUCCESS Register instance of class [547], object handle=2097154
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [551] (RO)
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [551] (RO)
DEBUG [main] portico.lrc: ATTEMPT Register instance of class [545] , name=null
INFO  [main] portico.lrc: SUCCESS Register instance of class [545], object handle=2097155
DEBUG [main] portico.lrc: @REMOTE Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] ACHIEVED synchronization point [readyToRun]
DEBUG [main] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToRun]
DEBUG [main] portico.lrc: @REMOTE Discover object: owner=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf, object=4194304, class=542, owned=[544, 502, 543]
INFO  [main] portico.lrc: DISCOVER object [4194304] registeredAs=542, discoveredAs=542
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [4194304] with attributes [544, 543] (RO)
DEBUG [main] portico.lrc: @REMOTE Discover object: owner=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf, object=4194305, class=542, owned=[544, 543, 502]
INFO  [main] portico.lrc: DISCOVER object [4194305] registeredAs=542, discoveredAs=542
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [4194305] with attributes [544, 543] (RO)
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [797] with parameters [802, 707, 803, 708, 804, 709, 805, 710] (RO)
DEBUG [main] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] ACHIEVED synchronization point [readyToRun]
DEBUG [main] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToRun]
INFO  [main] portico.lrc: NOTICE  Federate [GLDFederate] achieved sync point [readyToRun]
DEBUG [main] portico.lrc: @REMOTE Federate [GLDFederate] ACHIEVED synchronization point [readyToRun]
INFO  [main] portico.lrc: Federation SYNCHRONIZED on point [readyToRun], queued callback
DEBUG [main] portico.lrc: ATTEMPT Send interaction [813] with parameters [816, 817, 818, 814, 815] @0.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [813] with parameters [816, 817, 818, 814, 815] @0.1
DEBUG [main] portico.lrc: ATTEMPT Send interaction [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @0.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @0.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [548, 549, 550] @0.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [548, 549, 550] @0.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [548, 549, 550] @0.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [548, 549, 550] @0.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097155], attributes [546] @0.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097155], attributes [546] @0.1
DEBUG [main] portico.lrc: REQUEST Time advance request for [GLDFederate] to [1.0]
INFO  [main] portico.lrc: PENDING Requested time advance for [GLDFederate] to [1.0], waiting for grant...
DEBUG [main] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [1.0]
DEBUG [main] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [1.0]
DEBUG [main] portico.lrc: @REMOTE Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] subscribed to interaction class [745]
DEBUG [main] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [1.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [1.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [1.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [1.0]
DEBUG [main] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [2.0]
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [806] with parameters [707, 708, 709, 710, 808, 810] @1.0
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [4194304] with attributes [543] @1.0
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [4194305] with attributes [543] @1.0
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [1.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [1.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [1.0]
DEBUG [main] portico.lrc: ATTEMPT Send interaction [813] with parameters [816, 817, 818, 814, 815] @1.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [813] with parameters [816, 817, 818, 814, 815] @1.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [549, 550] @1.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [549, 550] @1.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [549, 550] @1.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [549, 550] @1.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097155], attributes [546] @1.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097155], attributes [546] @1.1
DEBUG [main] portico.lrc: REQUEST Time advance request for [GLDFederate] to [2.0]
INFO  [main] portico.lrc: PENDING Requested time advance for [GLDFederate] to [2.0], waiting for grant...
DEBUG [main] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [2.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [2.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [2.0]
DEBUG [main] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [3.0]
DEBUG [main] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [2.0]
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [806] with parameters [707, 708, 709, 710, 808, 810] @2.0
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [2.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [2.0]
DEBUG [main] portico.lrc: ATTEMPT Send interaction [813] with parameters [816, 817, 818, 814, 815] @2.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [813] with parameters [816, 817, 818, 814, 815] @2.1
DEBUG [main] portico.lrc: ATTEMPT Send interaction [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @2.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @2.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [548, 549, 550] @2.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [548, 549, 550] @2.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [548, 549, 550] @2.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [548, 549, 550] @2.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097155], attributes [546] @2.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097155], attributes [546] @2.1
DEBUG [main] portico.lrc: REQUEST Time advance request for [GLDFederate] to [3.0]
INFO  [main] portico.lrc: PENDING Requested time advance for [GLDFederate] to [3.0], waiting for grant...
DEBUG [main] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [3.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [3.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [3.0]
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [806] with parameters [707, 708, 709, 710, 808, 810] @3.0
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [3.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [3.0]
DEBUG [main] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [3.0]
DEBUG [main] portico.lrc: ATTEMPT Send interaction [813] with parameters [816, 817, 818, 814, 815] @3.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [813] with parameters [816, 817, 818, 814, 815] @3.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [548, 549, 550] @3.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [548, 549, 550] @3.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [548, 549, 550] @3.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [548, 549, 550] @3.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097155], attributes [546] @3.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097155], attributes [546] @3.1
DEBUG [main] portico.lrc: REQUEST Time advance request for [GLDFederate] to [4.0]
INFO  [main] portico.lrc: PENDING Requested time advance for [GLDFederate] to [4.0], waiting for grant...
DEBUG [main] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [4.0]
DEBUG [main] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [4.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [4.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [4.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [4.0]
DEBUG [main] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [4.0]
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [806] with parameters [707, 708, 709, 710, 808, 810] @4.0
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [4.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [4.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [4.0]
DEBUG [main] portico.lrc: ATTEMPT Send interaction [813] with parameters [816, 817, 818, 814, 815] @4.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [813] with parameters [816, 817, 818, 814, 815] @4.1
DEBUG [main] portico.lrc: ATTEMPT Send interaction [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @4.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @4.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [549, 550] @4.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [549, 550] @4.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [549, 550] @4.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [549, 550] @4.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097155], attributes [546] @4.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097155], attributes [546] @4.1
DEBUG [main] portico.lrc: REQUEST Time advance request for [GLDFederate] to [5.0]
INFO  [main] portico.lrc: PENDING Requested time advance for [GLDFederate] to [5.0], waiting for grant...
DEBUG [main] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [5.0]
DEBUG [main] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [5.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [5.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [5.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [5.0]
DEBUG [main] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [5.0]
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [806] with parameters [707, 708, 709, 710, 808, 810] @5.0
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [5.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [5.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [5.0]
DEBUG [main] portico.lrc: ATTEMPT Send interaction [813] with parameters [816, 817, 818, 814, 815] @5.1
INFO  [main] portico.lrc: SUCCESS Sent interaction [813] with parameters [816, 817, 818, 814, 815] @5.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097153], attributes [548, 549, 550] @5.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097153], attributes [548, 549, 550] @5.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097154], attributes [548, 549, 550] @5.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097154], attributes [548, 549, 550] @5.1
DEBUG [main] portico.lrc: ATTEMPT Update object [2097155], attributes [546] @5.1
INFO  [main] portico.lrc: SUCCESS Updated object [2097155], attributes [546] @5.1
DEBUG [main] portico.lrc: REQUEST Time advance request for [GLDFederate] to [6.0]

The complete log for TestFederate (the broken one):

DEBUG [TestFederation.TestFederate.main()] portico.lrc: Creating new LRC
DEBUG [TestFederation.TestFederate.main()] portico.lrc: Portico version: 2.1.0 (build 3)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: Interface: HLA13
DEBUG [TestFederation.TestFederate.main()] portico.lrc: Messaging framework configuration complete
INFO  [TestFederation.TestFederate.main()] portico.lrc: LRC initialized (HLA version: HLA13)
INFO  [TestFederation.TestFederate.main()] portico.lrc: Opening LRC Connection
INFO  [TestFederation.TestFederate.main()] portico.lrc.jgroups: jgroups connection is up and running
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Join federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to federation [TestFederation]
-------------------------------------------------------------------
GMS: address=vagrant-41004, cluster=TestFederation, physical address=127.0.0.1:40360
-------------------------------------------------------------------
DEBUG [TestFederation.TestFederate.main()] portico.lrc.jgroups: SUCCESS Connected to channel [TestFederation]
DEBUG [Regular] portico.lrc.jgroups: (GMS) findCoordinator(vagrant-41004)
DEBUG [Regular] portico.lrc.jgroups: (GMS) setManifest(vagrant-34351)
DEBUG [Regular] portico.lrc.jgroups: Received updated manifest from 518a6613-4b3e-455d-919a-fa89451ded0f
DEBUG [Regular] portico.lrc.jgroups: Installed new manifest (follows)
DEBUG [Regular] portico.lrc.jgroups: 
-----------------------------------
Manifest: channel=TestFederation
-----------------------------------
 Version        = 5
 Local UUID     = f4b579c4-5c40-4a8a-8a07-94191fcf1e88
 Highest Handle = 3
 Is Federation  = true
 Channel members: 3
  (application) id=3, uuid=f4b579c4-5c40-4a8a-8a07-94191fcf1e88
  (application) id=2, uuid=dc314b95-14b2-4f3e-b4b8-3514c9535052
     (federate) id=1, name=FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0, uuid=518a6613-4b3e-455d-919a-fa89451ded0f **CO-ORDINATOR**
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(vagrant-38664)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=GLDFederate, federation=TestFederation, source=dc314b95-14b2-4f3e-b4b8-3514c9535052
INFO  [Regular] portico.lrc.jgroups: Federate [GLDFederate] joined federation [TestFederation]
DEBUG [TestFederation.TestFederate.main()] portico.lrc.jgroups: Validate that [0] modules can merge successfully with the existing FOM
DEBUG [TestFederation.TestFederate.main()] portico.lrc.jgroups: Modules can be merged successfully, continue with join
DEBUG [TestFederation.TestFederate.main()] portico.lrc.jgroups: REQUEST joinFederation: federate=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf, federation=TestFederation
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(vagrant-41004)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf, federation=TestFederation, source=f4b579c4-5c40-4a8a-8a07-94191fcf1e88
INFO  [Regular] portico.lrc.jgroups: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] joined federation [TestFederation]
INFO  [TestFederation.TestFederate.main()] portico.lrc.jgroups: SUCCESS Joined federation with name=TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:1,name:FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] by local federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [Regular] portico.lrc: @REMOTE Synchronization point [readyToResign] ANNOUNCED by [null]
INFO  [Regular] portico.lrc: Synchronization point [readyToResign] ANNOUNCED by [null] to [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [Regular] portico.lrc: @REMOTE Synchronization point [readyToPopulate] ANNOUNCED by [null]
INFO  [Regular] portico.lrc: Synchronization point [readyToPopulate] ANNOUNCED by [null] to [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [Regular] portico.lrc: @REMOTE Synchronization point [readyToRun] ANNOUNCED by [null]
INFO  [Regular] portico.lrc: Synchronization point [readyToRun] ANNOUNCED by [null] to [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:2,name:GLDFederate] by local federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Joined federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to federation [TestFederation]: handle=3
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Subscribe to interaction class [782]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Subscribed to interaction class [782]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Publish interaction class [716]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Published interaction class [716]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Publish interaction class [724]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Published interaction class [724]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [716] with parameters [707, 708, 709, 710, 717, 718, 719] (RO)
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [716] with parameters [707, 708, 709, 710, 717, 718, 719] (RO)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: REQUEST Enable time constrained for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
INFO  [TestFederation.TestFederate.main()] portico.lrc: PENDING Enable time constrained PENDING for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: DISCARD Discovery of object (not subscribed): object=4194302
DEBUG [TestFederation.TestFederate.main()] portico.lrc: DISCARD Discovery of object (not subscribed): object=1
DEBUG [TestFederation.TestFederate.main()] portico.lrc: DISCARD Discovery of object (not subscribed): object=2097151
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ENABLE time constrained
INFO  [TestFederation.TestFederate.main()] portico.lrc: ENABLED time constrained for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: REQUEST Enable time regulation for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]: fedtime=0.0, lookahead=0.1
INFO  [TestFederation.TestFederate.main()] portico.lrc: PENDING Enable time regulation PENDING for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ENABLE time regulation (fedtime=0.0, lookahead=0.1)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ENABLED time regulating for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] (fedtime=0.0)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] published interaction class [724]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] published interaction class [716]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] published interaction class [813]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] published interaction class [819]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] subscribed to interaction class [806]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] subscribed to interaction class [782]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] subscribed to interaction class [797]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] published object class [547] with attributes [548, 549, 550, 502, 551]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] published object class [545] with attributes [546, 502]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] subscribed to object class [542] with attributes [544, 543]]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] ACHIEVED synchronization point [readyToPopulate]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToPopulate]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] ACHIEVED synchronization point [readyToPopulate]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToPopulate]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: REQUEST Enable asynchronous delivery for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Enabled asynchronous delivery for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Publish interaction class [797]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Published interaction class [797]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Publish interaction class [806]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Published interaction class [806]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Subscribe to interaction class [813]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Subscribed to interaction class [813]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Subscribe to interaction class [819]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Subscribed to interaction class [819]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Publish [542] with attributes [544, 543]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Published [542] with attributes [544, 502, 543]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Subscribe to [545] with attributes [546]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Subscribeed to [545] with attributes [546]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Subscribe to [547] with attributes [548, 549, 550, 551]
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Subscribeed to [547] with attributes [548, 549, 550, 551]
INFO  [TestFederation.TestFederate.main()] portico.lrc: NOTICE  Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] achieved sync point [readyToPopulate]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Received INTERACTION [716] with parameters [720, 721, 722, 723, 717, 718, 719] (RO)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: DISCARD interaction of class [716]: no subscription
DEBUG [TestFederation.TestFederate.main()] portico.lrc: (veto) Interaction ignored: not subscribed
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] ACHIEVED synchronization point [readyToPopulate]
INFO  [TestFederation.TestFederate.main()] portico.lrc: Federation SYNCHRONIZED on point [readyToPopulate], queued callback
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Discover object: owner=GLDFederate, object=2097153, class=547, owned=[548, 550, 551, 502, 549]
INFO  [TestFederation.TestFederate.main()] portico.lrc: DISCOVER object [2097153] registeredAs=547, discoveredAs=547
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Received object UPDATE [2097153] with attributes [551] (RO)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Discover object: owner=GLDFederate, object=2097154, class=547, owned=[502, 551, 550, 548, 549]
INFO  [TestFederation.TestFederate.main()] portico.lrc: DISCOVER object [2097154] registeredAs=547, discoveredAs=547
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Received object UPDATE [2097154] with attributes [551] (RO)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Discover object: owner=GLDFederate, object=2097155, class=545, owned=[502, 546]
INFO  [TestFederation.TestFederate.main()] portico.lrc: DISCOVER object [2097155] registeredAs=545, discoveredAs=545
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] ACHIEVED synchronization point [readyToRun]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToRun]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Register instance of class [542] , name=null
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Register instance of class [542], object handle=4194304
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Update object [4194304], attributes [544, 543] (RO)
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Updated object [4194304], attributes [544, 543] (RO)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Register instance of class [542] , name=null
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Register instance of class [542], object handle=4194305
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Update object [4194305], attributes [544, 543] (RO)
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Updated object [4194305], attributes [544, 543] (RO)
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [797] with parameters [802, 707, 803, 708, 804, 709, 805, 710] (RO)
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [797] with parameters [802, 707, 803, 708, 804, 709, 805, 710] (RO)
INFO  [TestFederation.TestFederate.main()] portico.lrc: NOTICE  Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] achieved sync point [readyToRun]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] ACHIEVED synchronization point [readyToRun]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: (veto) still waiting for federation to synchronize on point [readyToRun]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: @REMOTE Federate [GLDFederate] ACHIEVED synchronization point [readyToRun]
INFO  [TestFederation.TestFederate.main()] portico.lrc: Federation SYNCHRONIZED on point [readyToRun], queued callback
DEBUG [TestFederation.TestFederate.main()] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [1.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @1.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @1.0
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Update object [4194304], attributes [543] @1.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Updated object [4194304], attributes [543] @1.0
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Update object [4194305], attributes [543] @1.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Updated object [4194305], attributes [543] @1.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [1.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [1.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [1.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [813] with parameters [816, 817, 818, 814, 815] @0.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @0.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097154] with attributes [548, 549, 550] @0.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097155] with attributes [546] @0.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097153] with attributes [548, 549, 550] @0.1
DEBUG [Thread-1] portico.lrc: @REMOTE Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] subscribed to interaction class [745]
DEBUG [Thread-1] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [1.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [1.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [1.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [1.0]
DEBUG [Thread-1] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [2.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [1.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [1.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [1.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @2.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @2.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [2.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [2.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [2.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [2.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [2.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @3.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @3.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [3.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [3.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [3.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [813] with parameters [816, 817, 818, 814, 815] @1.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097155] with attributes [546] @1.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097154] with attributes [549, 550] @1.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097153] with attributes [549, 550] @1.1
DEBUG [Thread-1] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [2.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [2.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [2.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [813] with parameters [816, 817, 818, 814, 815] @2.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @2.1
DEBUG [Thread-1] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [3.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @4.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @4.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [4.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [4.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097153] with attributes [548, 549, 550] @2.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097154] with attributes [548, 549, 550] @2.1
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [4.0]
DEBUG [Thread-1] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [3.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [3.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097155] with attributes [546] @2.1
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [3.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [813] with parameters [816, 817, 818, 814, 815] @3.1
DEBUG [Thread-1] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [4.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [4.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [4.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [4.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [4.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @5.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @5.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [5.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [5.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [5.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097153] with attributes [548, 549, 550] @3.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097154] with attributes [548, 549, 550] @3.1
DEBUG [Thread-1] portico.lrc: Federate [GLDFederate] requests ADVANCE to time [4.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [GLDFederate] to time [4.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received object UPDATE [2097155] with attributes [546] @3.1
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [GLDFederate] to time [4.0]
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [813] with parameters [816, 817, 818, 814, 815] @4.1
DEBUG [Thread-1] portico.lrc: @REMOTE Received INTERACTION [819] with parameters [820, 821, 822, 823, 824, 825, 826, 827] @4.1
DEBUG [Thread-1] portico.lrc: Federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] requests ADVANCE to time [5.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [5.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [5.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [FederationManager-e4f4eeb9-85af-423f-8b82-44eb9a670de0] to time [5.0]
DEBUG [Thread-1] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to time [5.0]
DEBUG [TestFederation.TestFederate.main()] portico.lrc: ATTEMPT Send interaction [806] with parameters [707, 708, 709, 710, 808, 810] @6.0
INFO  [TestFederation.TestFederate.main()] portico.lrc: SUCCESS Sent interaction [806] with parameters [707, 708, 709, 710, 808, 810] @6.0
DEBUG [Thread-1] portico.lrc: REQUEST Time advance request for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [6.0]
INFO  [Thread-1] portico.lrc: PENDING Requested time advance for [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] to [6.0], waiting for grant...
DEBUG [Thread-1] portico.lrc: Federate [TestFederate-c2225aef-70de-4abb-8b71-fe48b7606fcf] requests ADVANCE to time [6.0]
timpokorny commented 6 years ago

G'day Tom, I suspect this is related to a bit of oddity in the way the LRC unilaterally calculates what is can advance to. This will change very soon as the time function moves to a central broker (and should make the whole logic overall much simpler). Let's put a pin in it until we can test against that and then re-test. Assigning this to the same project.