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!
Federate A is regulating/constrained, with lookahead 0. Uses NMRA.
Federate B is timestepped, uses TAR.
TEST CASE 1
Federate A:
issues NMRA(inf)
receives attribute update and interaction
is granted time T
sends an interaction timestamped with time T
Federate B:
timesteps, issueing an update/interaction per step (TSO)
Observations for A:
the send interaction timestamped at T fails
lbts:2425.000000001 (why not 2425 ? - Guess the tiny lookahead is added)
Zero-lookahead detected: Adding 10^-9 to lookahead (I.e. NMRA is not really supported ?)
See logfile 1 below.
TEST CASE 2
Federate A is adapted to send the interaction timestamped with T+1 (by adding 1 to the time in the send call).
the send interaction now succeeds
federate fails at the next call to NMRA ( with the error message ... Time has already passed ...)
Sending the interaction with timestamp lbts, T+5 or T+10 yields the same error.
See logfile 2 below.
TEST CASE 3
Similar to test case 2:
NMRA is changed to NMR, using a lookahead of 0.1.
I.e. enableTimeRegulation with LA=0.1.
Send interaction with timestamp is current time+LA.
Get same error, see logfile 3 below.
Note that in the logs the messages from Portico and from the application Logger are mixed. For each one the order is correct, but not the timing of print on the console.
LOGFILE 1
run:
DEBUG [main] portico.lrc: Creating new LRC
DEBUG [main] portico.lrc: Portico version: 2.1.0 (build 3)
DEBUG [main] portico.lrc: Interface: IEEE1516e
TRACE [main] portico.lrc: Provided connection implementation is "org.portico.bindings.jgroups.JGroupsConnection"
TRACE [main] portico.lrc: Trying to load connection class: org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: ATTEMPT create IConnection, class= class org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: SUCCESS created IConnection, class= class org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: Applying modules using component keyword: lrc1516e
TRACE [main] portico.lrc: STARTING Apply module [lrc1516-callback] to LRC
TRACE [main] portico.lrc: Applied [0/11] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc1516e-callback] to LRC
TRACE [main] portico.lrc: Applied [24/24] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc13-callback] to LRC
TRACE [main] portico.lrc: Applied [0/24] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc-base] to LRC
TRACE [main] portico.lrc: Applied [82/92] handlers
DEBUG [main] portico.lrc: Messaging framework configuration complete
INFO [main] portico.lrc: LRC initialized (HLA version: IEEE1516e)
INFO [main] portico.lrc: Opening LRC Connection
INFO [main] portico.lrc.jgroups: jgroups connection is up and running
HOME=C:\Users\bergtwvd\AppData\Local\Home
1::22:41:24.066::damageserver.DamageServer::main::federationName = TheWorld
1::22:41:24.066::damageserver.DamageServer::main::federateName = null
1::22:41:24.066::damageserver.DamageServer::main::connectAttempts = 0
1::22:41:24.066::damageserver.DamageServer::main::logFile = null
1::22:41:24.066::damageserver.DamageServer::main::logLevel = INFO
1::22:41:24.066::damageserver.Federate::connect::Attempt #1 ...
1::22:41:24.066::damageserver.Federate::connect::Connected to RTI
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml
TRACE [main] portico.lrc.merger: Beginning merge of 2 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
TRACE [main] portico.lrc.merger: -> Inserting class [HLAinteractionRoot.DamageReport]
TRACE [main] portico.lrc.merger: -> Inserting class [HLAinteractionRoot.DamageReport.EntityDamageReport]
DEBUG [main] portico.lrc: ATTEMPT Create federation execution [TheWorld]
TRACE [main] portico.lrc.jgroups: ATTEMPT Connecting to channel [TheWorld]
-------------------------------------------------------------------
GMS: address=PC-12505-31499, cluster=TheWorld, physical address=192.168.2.8:64806
-------------------------------------------------------------------
DEBUG [main] portico.lrc.jgroups: SUCCESS Connected to channel [TheWorld]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=0, source=PC-12505-31499
DEBUG [Regular] portico.lrc.jgroups: (GMS) findCoordinator(PC-12505-31499)
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=53683, source=PC-12505-56321
DEBUG [Regular] portico.lrc.jgroups: (GMS) setManifest(PC-12505-56321)
DEBUG [Regular] portico.lrc.jgroups: Received updated manifest from 06143063-fe1b-4546-8b43-f502eb751235
DEBUG [Regular] portico.lrc.jgroups: Installed new manifest (follows)
DEBUG [Regular] portico.lrc.jgroups:
-----------------------------------
Manifest: channel=TheWorld
-----------------------------------
Version = 60
Local UUID = 7a233d81-4a08-446a-8f51-afcdb590eba6
Highest Handle = 16
Is Federation = true
Channel members: 2
(federate) id=1, name=TestFederate, uuid=06143063-fe1b-4546-8b43-f502eb751235 **CO-ORDINATOR**
(application) id=16, uuid=7a233d81-4a08-446a-8f51-afcdb590eba6
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-56321
DEBUG [main] portico.lrc.jgroups: REQUEST createFederation: name=TheWorld
1::22:41:27.935::damageserver.Federate::join::Didn't create federation, it already existed
ERROR [main] portico.lrc.jgroups: FAILURE createFederation: already exists, name=TheWorld
DEBUG [main] portico.lrc: org.portico.lrc.compat.JFederationExecutionAlreadyExists: federation exists: TheWorld
DEBUG [main] portico.lrc: ATTEMPT Join federate [Federate-1476218483785] to federation [TheWorld]
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml
DEBUG [main] portico.lrc: Parsed [2] additional FOM modules
DEBUG [main] portico.lrc.jgroups: Validate that [2] modules can merge successfully with the existing FOM
TRACE [main] portico.lrc.merger: Beginning merge of 3 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml] into combined FOM
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
DEBUG [main] portico.lrc.jgroups: Modules can be merged successfully, continue with join
DEBUG [main] portico.lrc.jgroups: REQUEST joinFederation: federate=Federate-1476218483785, federation=TheWorld
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=22, source=PC-12505-31499
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(PC-12505-31499)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=Federate-1476218483785, federation=TheWorld, source=7a233d81-4a08-446a-8f51-afcdb590eba6
INFO [Regular] portico.lrc.jgroups: Federate [Federate-1476218483785] joined federation [TheWorld]
INFO [main] portico.lrc.jgroups: SUCCESS Joined federation with name=Federate-1476218483785
DEBUG [main] portico.lrc.jgroups: Merging 2 additional FOM modules that we receive with join request
TRACE [main] portico.lrc.merger: Beginning merge of 3 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml] into combined FOM
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
TRACE [main] portico.lrc: Created Mom.Federation object, added to Repository (undiscovered)
TRACE [main] portico.lrc: Created Mom.Federate(Federate-1476218483785), queued discovery notification
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=47828, source=PC-12505-31499
TRACE [main] portico.lrc: joined federation, waiting for RoleCalls from [16, 1]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=55670, source=PC-12505-56321
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:1,name:TestFederate] by local federate [Federate-1476218483785]
TRACE [Regular] portico.lrc: Created Mom.Federate(TestFederate), queued discovery notification
DEBUG [Regular] portico.lrc: (RoleCall) Adding undiscoverd instance [2] following RoleCall notification
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=567, source=PC-12505-31499
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-56321
INFO [main] portico.lrc: SUCCESS Joined federate [Federate-1476218483785] to federation [TheWorld]: handle=16
1::22:41:28.265::damageserver.Federate::join::Joined Federation
DEBUG [main] portico.lrc: REQUEST Enable asynchronous delivery for [Federate-1476218483785]
1::22:41:28.265::damageserver.Federate::enableTimePolicy::Enable time policy
DEBUG [main] portico.lrc: SUCCESS Enabled asynchronous delivery for [Federate-1476218483785]
DEBUG [main] portico.lrc: REQUEST Enable time constrained for [Federate-1476218483785]
INFO [main] portico.lrc: PENDING Enable time constrained PENDING for [Federate-1476218483785]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=214, source=PC-12505-31499
TRACE [main] portico.lrc: @REMOTE Received MOM object discovery for federate [MOM.Federate(Federate-1476218483785)]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=31457265
TRACE [main] portico.lrc: @REMOTE Received MOM object discovery for federate [MOM.Federate(TestFederate)]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=1
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [2] with attributes [788, 784] (RO)
DEBUG [main] portico.lrc: DISCARD reflection for object [2]: object unknown
DEBUG [main] portico.lrc: (veto) Reflection ignored: object unknown
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [1070] with parameters [1081, 1073] (RO)
DEBUG [main] portico.lrc: DISCARD interaction of class [1070]: no subscription
DEBUG [main] portico.lrc: (veto) Interaction ignored: not subscribed
DEBUG [main] portico.lrc: Federate [TestFederate] requests ADVANCE to time [2424.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate] to time [2424.0]
1::22:41:28.265::damageserver.FederateAmbassador::timeConstrainedEnabled::timeConstrainedEnabled Time=0.0
DEBUG [main] portico.lrc: @REMOTE Federate [Federate-1476218483785] requests ENABLE time constrained
INFO [main] portico.lrc: ENABLED time constrained for [Federate-1476218483785]
TRACE [main] portico.lrc: CALLBACK timeConstrainedEnabled(time=0.0)
TRACE [main] portico.lrc: timeConstrainedEnabled() callback complete
DEBUG [main] portico.lrc: REQUEST Enable time regulation for [Federate-1476218483785]: fedtime=0.0, lookahead=0.0
DEBUG [main] portico.lrc: Zero-lookahead detected: Adding 10^-9 to lookahead
DEBUG [main] portico.lrc: Insubordinate activity will not be permitted!
INFO [main] portico.lrc: PENDING Enable time regulation PENDING for [Federate-1476218483785]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=256, source=PC-12505-31499
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-56321
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-56321
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate] to time [2424.0]
DEBUG [main] portico.lrc: @REMOTE Federate [Federate-1476218483785] requests ENABLE time regulation (fedtime=0.0, lookahead=1.0E-9)
DEBUG [main] portico.lrc: ENABLED time regulating for [Federate-1476218483785] (fedtime=2424.999999999)
1::22:41:29.279::damageserver.FederateAmbassador::timeRegulationEnabled::timeRegulationEnabled Time=2424.999999999
TRACE [main] portico.lrc: CALLBACK timeRegulationEnabled(time=2424.999999999)
TRACE [main] portico.lrc: timeRegulationEnabled() callback complete
1::22:41:29.279::damageserver.Federate::enableTimePolicy::Time policy enabled
DEBUG [main] portico.lrc: ATTEMPT Subscribe to [789] with attributes [788, 784]
DEBUG [main] portico.lrc: Queued Discover callback for instance [2] after subscription to class [789]
INFO [main] portico.lrc: SUCCESS Subscribeed to [789] with attributes [788, 784]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=433, source=PC-12505-31499
DEBUG [main] portico.lrc: ATTEMPT Subscribe to interaction class [1070]
INFO [main] portico.lrc: SUCCESS Subscribed to interaction class [1070]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=267, source=PC-12505-31499
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [504]
1::22:41:29.294::damageserver.Federate::publishAndSubscribe::Published and Subscribed
INFO [main] portico.lrc: SUCCESS Published interaction class [504]
1::22:41:29.294::damageserver.Federate::start::Start ...
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=236, source=PC-12505-31499
1::22:41:29.294::damageserver.Federate::start::nextMessageRequestAvailable
DEBUG [main] portico.lrc: REQUEST Next event request for [Federate-1476218483785]: time=1.7976931348623157E308
DEBUG [main] portico.lrc: REQUEST Time advance request for [Federate-1476218483785] to [2425.0]
INFO [main] portico.lrc: PENDING Requested time advance for [Federate-1476218483785] to [2425.0], waiting for grant...
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-31499
DEBUG [main] portico.lrc: Federate [TestFederate] requests ADVANCE to time [2425.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [Federate-1476218483785] to time [2425.0]
1::22:41:29.294::damageserver.FederateAmbassador::discoverObjectInstance::discoverObjectInstance name=HLA2
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate] to time [2425.0]
DEBUG [main] portico.lrc: @REMOTE Discover object: owner=TestFederate, object=2, class=789, owned=[788, 1242, 804, 803, 784]
INFO [main] portico.lrc: DISCOVER object [2] registeredAs=789, discoveredAs=789
TRACE [main] portico.lrc: CALLBACK discoverObjectInstance(object=2,class=789,name=HLA2)
TRACE [main] portico.lrc: discoverObjectInstance() callback complete
DEBUG [main] portico.lrc: ATTEMPT Request update of object [2] for attributes=[788, 784]
INFO [main] portico.lrc: SUCCESS Requested update of object [2] for attributes=[788, 784]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=412, source=PC-12505-31499
DEBUG [main] portico.lrc: Federate [Federate-1476218483785] requests ADVANCE to time [2425.0]
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [2] with attributes [788, 784] @2425.0
TRACE [main] portico.lrc: CALLBACK reflectAttributeValues(object=2,attributes={788(8b),784(50b)},time=2425.0) (TSO)
1::22:41:29.310::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues: sentOrdering=TIMESTAMP receivedOrdering=TIMESTAMP time=2425.0
1::22:41:29.310::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues for name=HLA2
1::22:41:29.326::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues ET=(1.2.3.4.5.6.0)
TRACE [main] portico.lrc: reflectAttributeValues() callback complete
1::22:41:29.341::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues SV=(DRM_FPW;w=(x=3958995.8260064786;y=836358.1693870248;z=4934322.5433315);f=false;o=(psi=0.0;theta=0.0;phi=0.0);v=(x=10.0;y=0.0;z=0.0))
DEBUG [main] portico.lrc: @REMOTE Request object update: object=2, attributes=[788, 784], sourceFederate=Federate-1476218483785
DEBUG [main] portico.lrc: (veto) don't own any attributes
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [1070] with parameters [1081, 1073] @2425.0
TRACE [main] portico.lrc: CALLBACK receiveInteraction(class=1070,parameters={1081(7b),1073(24b)},time=2425.0) (TSO)
1::22:41:29.341::damageserver.FederateAmbassador::receiveInteraction::receiveInteraction: sentOrdering=TIMESTAMP receivedOrdering=TIMESTAMP time=2425.0
TRACE [main] portico.lrc: receiveInteraction() callback complete
1::22:41:29.341::damageserver.FederateAmbassador::createMunitionDetonationInteraction::FiringObjectIdentifier: ME!
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate] to time [2425.0]
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [Federate-1476218483785] to time [2425.0]
1::22:41:29.341::damageserver.FederateAmbassador::createMunitionDetonationInteraction::DetonationLocation: (x=10.0;y=11.0;z=12.0)
TRACE [main] portico.lrc: CALLBACK timeAdvanceGrant(time=2425.0)
TRACE [main] portico.lrc: timeAdvanceGrant() callback complete
1::22:41:29.341::damageserver.FederateAmbassador::receiveInteraction::TSO
1::22:41:29.341::damageserver.FederateAmbassador::timeAdvanceGrant::timeAdvanceGrant Time=2425.0
1::22:41:29.341::damageserver.Federate::sendDamageReport::sendDamageReport at time=2425.0
1::22:41:29.341::damageserver.Federate::sendDamageReport::LITS=2425.0
DEBUG [main] portico.lrc: ATTEMPT Send interaction [504] with parameters [508, 505, 506] @2425.0
DEBUG [main] portico.lrc: org.portico.lrc.compat.JInvalidFederationTime: Time [2425.0] has already passed (lbts:2425.000000001)
Exception in thread "main" hla.rti1516e.exceptions.InvalidLogicalTime: org.portico.lrc.compat.JInvalidFederationTime: Time [2425.0] has already passed (lbts:2425.000000001)
Handler: Received shutdown signal
Handler: Wait for federate to finish
Handler: Exit
at org.portico.impl.hla1516e.Rti1516eAmbassador.sendInteraction(Rti1516eAmbassador.java:2336)
at damageserver.Federate.sendDamageReport(Federate.java:279)
at damageserver.Environment.detonation(Environment.java:86)
at damageserver.Federate.processTSOMunitionDetonations(Federate.java:247)
at damageserver.Federate.start(Federate.java:214)
at damageserver.DamageServer.main(DamageServer.java:106)
Caused by: org.portico.lrc.compat.JInvalidFederationTime: Time [2425.0] has already passed (lbts:2425.000000001)
at org.portico.lrc.LRCState.checkValidTime(LRCState.java:390)
at org.portico.lrc.services.object.handlers.outgoing.SendInteractionHandler.process(SendInteractionHandler.java:82)
at org.portico.utils.messaging.MessageSink.process(MessageSink.java:187)
at org.portico.impl.hla1516e.Impl1516eHelper.processMessage(Impl1516eHelper.java:130)
at org.portico.impl.hla1516e.Rti1516eAmbassador.processMessage(Rti1516eAmbassador.java:5559)
at org.portico.impl.hla1516e.Rti1516eAmbassador.sendInteraction(Rti1516eAmbassador.java:2302)
... 5 more
C:\Users\bergtwvd\AppData\Local\NetBeans\Cache\8.1\executor-snippets\run.xml:53: Java returned: 1
BUILD FAILED (total time: 6 seconds)
LOGFILE 2
run:
DEBUG [main] portico.lrc: Creating new LRC
DEBUG [main] portico.lrc: Portico version: 2.1.0 (build 3)
DEBUG [main] portico.lrc: Interface: IEEE1516e
TRACE [main] portico.lrc: Provided connection implementation is "org.portico.bindings.jgroups.JGroupsConnection"
TRACE [main] portico.lrc: Trying to load connection class: org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: ATTEMPT create IConnection, class= class org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: SUCCESS created IConnection, class= class org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: Applying modules using component keyword: lrc1516e
TRACE [main] portico.lrc: STARTING Apply module [lrc1516-callback] to LRC
TRACE [main] portico.lrc: Applied [0/11] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc1516e-callback] to LRC
TRACE [main] portico.lrc: Applied [24/24] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc13-callback] to LRC
TRACE [main] portico.lrc: Applied [0/24] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc-base] to LRC
TRACE [main] portico.lrc: Applied [82/92] handlers
DEBUG [main] portico.lrc: Messaging framework configuration complete
INFO [main] portico.lrc: LRC initialized (HLA version: IEEE1516e)
INFO [main] portico.lrc: Opening LRC Connection
INFO [main] portico.lrc.jgroups: jgroups connection is up and running
HOME=C:\Users\bergtwvd\AppData\Local\Home
1::23:16:50.354::damageserver.DamageServer::main::federationName = TheWorld
1::23:16:50.369::damageserver.DamageServer::main::federateName = null
1::23:16:50.369::damageserver.DamageServer::main::connectAttempts = 0
1::23:16:50.369::damageserver.DamageServer::main::logFile = null
1::23:16:50.369::damageserver.DamageServer::main::logLevel = INFO
1::23:16:50.369::damageserver.Federate::connect::Attempt #1 ...
1::23:16:50.369::damageserver.Federate::connect::Connected to RTI
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml
TRACE [main] portico.lrc.merger: Beginning merge of 2 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
TRACE [main] portico.lrc.merger: -> Inserting class [HLAinteractionRoot.DamageReport]
TRACE [main] portico.lrc.merger: -> Inserting class [HLAinteractionRoot.DamageReport.EntityDamageReport]
DEBUG [main] portico.lrc: ATTEMPT Create federation execution [TheWorld]
TRACE [main] portico.lrc.jgroups: ATTEMPT Connecting to channel [TheWorld]
-------------------------------------------------------------------
GMS: address=PC-12505-28450, cluster=TheWorld, physical address=192.168.2.8:52433
-------------------------------------------------------------------
DEBUG [main] portico.lrc.jgroups: SUCCESS Connected to channel [TheWorld]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=0, source=PC-12505-28450
DEBUG [Regular] portico.lrc.jgroups: (GMS) findCoordinator(PC-12505-28450)
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=53683, source=PC-12505-41586
DEBUG [Regular] portico.lrc.jgroups: (GMS) setManifest(PC-12505-41586)
DEBUG [Regular] portico.lrc.jgroups: Received updated manifest from 42d792fb-82c5-41b1-a550-9fa6a36afbad
DEBUG [Regular] portico.lrc.jgroups: Installed new manifest (follows)
DEBUG [Regular] portico.lrc.jgroups:
-----------------------------------
Manifest: channel=TheWorld
-----------------------------------
Version = 4
Local UUID = 9e0de741-9af1-49f5-9fd5-31cf4fa470f4
Highest Handle = 2
Is Federation = true
Channel members: 2
(application) id=2, uuid=9e0de741-9af1-49f5-9fd5-31cf4fa470f4
(federate) id=1, name=TestFederate, uuid=42d792fb-82c5-41b1-a550-9fa6a36afbad **CO-ORDINATOR**
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-41586
DEBUG [main] portico.lrc.jgroups: REQUEST createFederation: name=TheWorld
ERROR [main] portico.lrc.jgroups: FAILURE createFederation: already exists, name=TheWorld
1::23:16:54.191::damageserver.Federate::join::Didn't create federation, it already existed
DEBUG [main] portico.lrc: org.portico.lrc.compat.JFederationExecutionAlreadyExists: federation exists: TheWorld
DEBUG [main] portico.lrc: ATTEMPT Join federate [Federate-1476220610104] to federation [TheWorld]
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml
DEBUG [main] portico.lrc: Parsed [2] additional FOM modules
DEBUG [main] portico.lrc.jgroups: Validate that [2] modules can merge successfully with the existing FOM
TRACE [main] portico.lrc.merger: Beginning merge of 3 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml] into combined FOM
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
DEBUG [main] portico.lrc.jgroups: Modules can be merged successfully, continue with join
DEBUG [main] portico.lrc.jgroups: REQUEST joinFederation: federate=Federate-1476220610104, federation=TheWorld
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=22, source=PC-12505-28450
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(PC-12505-28450)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=Federate-1476220610104, federation=TheWorld, source=9e0de741-9af1-49f5-9fd5-31cf4fa470f4
INFO [Regular] portico.lrc.jgroups: Federate [Federate-1476220610104] joined federation [TheWorld]
INFO [main] portico.lrc.jgroups: SUCCESS Joined federation with name=Federate-1476220610104
DEBUG [main] portico.lrc.jgroups: Merging 2 additional FOM modules that we receive with join request
TRACE [main] portico.lrc.merger: Beginning merge of 3 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml] into combined FOM
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
TRACE [main] portico.lrc: Created Mom.Federation object, added to Repository (undiscovered)
TRACE [main] portico.lrc: Created Mom.Federate(Federate-1476220610104), queued discovery notification
TRACE [main] portico.lrc: joined federation, waiting for RoleCalls from [1, 2]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=47828, source=PC-12505-28450
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=55670, source=PC-12505-41586
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:1,name:TestFederate] by local federate [Federate-1476220610104]
INFO [main] portico.lrc: SUCCESS Joined federate [Federate-1476220610104] to federation [TheWorld]: handle=2
TRACE [Regular] portico.lrc: Created Mom.Federate(TestFederate), queued discovery notification
DEBUG [Regular] portico.lrc: (RoleCall) Adding undiscoverd instance [2] following RoleCall notification
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=567, source=PC-12505-28450
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-41586
1::23:16:54.514::damageserver.Federate::join::Joined Federation
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-41586
1::23:16:54.514::damageserver.Federate::enableTimePolicy::Enable time policy
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-41586
DEBUG [main] portico.lrc: REQUEST Enable asynchronous delivery for [Federate-1476220610104]
DEBUG [main] portico.lrc: SUCCESS Enabled asynchronous delivery for [Federate-1476220610104]
DEBUG [main] portico.lrc: REQUEST Enable time constrained for [Federate-1476220610104]
INFO [main] portico.lrc: PENDING Enable time constrained PENDING for [Federate-1476220610104]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=214, source=PC-12505-28450
TRACE [main] portico.lrc: @REMOTE Received MOM object discovery for federate [MOM.Federate(Federate-1476220610104)]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=2097151
TRACE [main] portico.lrc: @REMOTE Received MOM object discovery for federate [MOM.Federate(TestFederate)]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=1
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [2] with attributes [788, 784] (RO)
DEBUG [main] portico.lrc: DISCARD reflection for object [2]: object unknown
DEBUG [main] portico.lrc: (veto) Reflection ignored: object unknown
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [1070] with parameters [1081, 1073] (RO)
DEBUG [main] portico.lrc: DISCARD interaction of class [1070]: no subscription
DEBUG [main] portico.lrc: (veto) Interaction ignored: not subscribed
1::23:16:54.514::damageserver.FederateAmbassador::timeConstrainedEnabled::timeConstrainedEnabled Time=0.0
DEBUG [main] portico.lrc: Federate [TestFederate] requests ADVANCE to time [10.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate] to time [10.0]
DEBUG [main] portico.lrc: @REMOTE Federate [Federate-1476220610104] requests ENABLE time constrained
INFO [main] portico.lrc: ENABLED time constrained for [Federate-1476220610104]
TRACE [main] portico.lrc: CALLBACK timeConstrainedEnabled(time=0.0)
TRACE [main] portico.lrc: timeConstrainedEnabled() callback complete
DEBUG [main] portico.lrc: REQUEST Enable time regulation for [Federate-1476220610104]: fedtime=0.0, lookahead=0.0
DEBUG [main] portico.lrc: Zero-lookahead detected: Adding 10^-9 to lookahead
DEBUG [main] portico.lrc: Insubordinate activity will not be permitted!
INFO [main] portico.lrc: PENDING Enable time regulation PENDING for [Federate-1476220610104]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=256, source=PC-12505-28450
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-41586
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [TestFederate] to time [10.0]
DEBUG [main] portico.lrc: @REMOTE Federate [Federate-1476220610104] requests ENABLE time regulation (fedtime=0.0, lookahead=1.0E-9)
DEBUG [main] portico.lrc: ENABLED time regulating for [Federate-1476220610104] (fedtime=10.999999999)
1::23:16:55.528::damageserver.FederateAmbassador::timeRegulationEnabled::timeRegulationEnabled Time=10.999999999
TRACE [main] portico.lrc: CALLBACK timeRegulationEnabled(time=10.999999999)
TRACE [main] portico.lrc: timeRegulationEnabled() callback complete
1::23:16:55.528::damageserver.Federate::enableTimePolicy::Time policy enabled
DEBUG [main] portico.lrc: ATTEMPT Subscribe to [789] with attributes [788, 784]
DEBUG [main] portico.lrc: Queued Discover callback for instance [2] after subscription to class [789]
INFO [main] portico.lrc: SUCCESS Subscribeed to [789] with attributes [788, 784]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=433, source=PC-12505-28450
DEBUG [main] portico.lrc: ATTEMPT Subscribe to interaction class [1070]
INFO [main] portico.lrc: SUCCESS Subscribed to interaction class [1070]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=267, source=PC-12505-28450
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [504]
INFO [main] portico.lrc: SUCCESS Published interaction class [504]
1::23:16:55.544::damageserver.Federate::publishAndSubscribe::Published and Subscribed
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=236, source=PC-12505-28450
1::23:16:55.544::damageserver.Federate::start::Start ...
DEBUG [main] portico.lrc: REQUEST Next event request for [Federate-1476220610104]: time=1.7976931348623157E308
1::23:16:55.544::damageserver.Federate::start::nextMessageRequestAvailable
DEBUG [main] portico.lrc: REQUEST Time advance request for [Federate-1476220610104] to [11.0]
INFO [main] portico.lrc: PENDING Requested time advance for [Federate-1476220610104] to [11.0], waiting for grant...
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-28450
DEBUG [main] portico.lrc: Federate [TestFederate] requests ADVANCE to time [11.0]
1::23:16:55.544::damageserver.FederateAmbassador::discoverObjectInstance::discoverObjectInstance name=HLA2
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate] to time [11.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [Federate-1476220610104] to time [11.0]
DEBUG [main] portico.lrc: @REMOTE Discover object: owner=TestFederate, object=2, class=789, owned=[784, 788, 803, 1242, 804]
INFO [main] portico.lrc: DISCOVER object [2] registeredAs=789, discoveredAs=789
TRACE [main] portico.lrc: CALLBACK discoverObjectInstance(object=2,class=789,name=HLA2)
TRACE [main] portico.lrc: discoverObjectInstance() callback complete
DEBUG [main] portico.lrc: ATTEMPT Request update of object [2] for attributes=[788, 784]
INFO [main] portico.lrc: SUCCESS Requested update of object [2] for attributes=[788, 784]
DEBUG [main] portico.lrc: Federate [Federate-1476220610104] requests ADVANCE to time [11.0]
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [2] with attributes [788, 784] @11.0
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=412, source=PC-12505-28450
TRACE [main] portico.lrc: CALLBACK reflectAttributeValues(object=2,attributes={788(8b),784(50b)},time=11.0) (TSO)
1::23:16:55.560::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues: sentOrdering=TIMESTAMP receivedOrdering=TIMESTAMP time=11.0
1::23:16:55.560::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues for name=HLA2
1::23:16:55.575::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues ET=(1.2.3.4.5.6.0)
TRACE [main] portico.lrc: reflectAttributeValues() callback complete
DEBUG [main] portico.lrc: @REMOTE Request object update: object=2, attributes=[788, 784], sourceFederate=Federate-1476220610104
1::23:16:55.591::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues SV=(DRM_FPW;w=(x=3934855.8260064786;y=836358.1693870248;z=4934322.5433315);f=false;o=(psi=0.0;theta=0.0;phi=0.0);v=(x=10.0;y=0.0;z=0.0))
DEBUG [main] portico.lrc: (veto) don't own any attributes
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [1070] with parameters [1081, 1073] @11.0
TRACE [main] portico.lrc: CALLBACK receiveInteraction(class=1070,parameters={1081(7b),1073(24b)},time=11.0) (TSO)
1::23:16:55.591::damageserver.FederateAmbassador::receiveInteraction::receiveInteraction: sentOrdering=TIMESTAMP receivedOrdering=TIMESTAMP time=11.0
TRACE [main] portico.lrc: receiveInteraction() callback complete
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [Federate-1476220610104] to time [11.0]
1::23:16:55.591::damageserver.FederateAmbassador::createMunitionDetonationInteraction::FiringObjectIdentifier: ME!
TRACE [main] portico.lrc: CALLBACK timeAdvanceGrant(time=11.0)
TRACE [main] portico.lrc: timeAdvanceGrant() callback complete
1::23:16:55.591::damageserver.FederateAmbassador::createMunitionDetonationInteraction::DetonationLocation: (x=10.0;y=11.0;z=12.0)
1::23:16:55.591::damageserver.FederateAmbassador::receiveInteraction::TSO
1::23:16:55.591::damageserver.FederateAmbassador::timeAdvanceGrant::timeAdvanceGrant Time=11.0
1::23:16:55.606::damageserver.Federate::sendDamageReport::LITS=11.0
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-41586
1::23:16:55.606::damageserver.Federate::sendDamageReport::sendDamageReport at time=12.0
DEBUG [main] portico.lrc: ATTEMPT Send interaction [504] with parameters [508, 505, 506] @12.0
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-41586
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=97, source=PC-12505-28450
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-41586
Exception in thread "main" hla.rti1516e.exceptions.LogicalTimeAlreadyPassed: org.portico.lrc.compat.JFederationTimeAlreadyPassed: Time 11.0 has already passed
INFO [main] portico.lrc: SUCCESS Sent interaction [504] with parameters [508, 505, 506] @12.0
DEBUG [main] portico.lrc: REQUEST Next event request for [Federate-1476220610104]: time=1.7976931348623157E308
DEBUG [main] portico.lrc: REQUEST Time advance request for [Federate-1476220610104] to [11.0]
DEBUG [main] portico.lrc: org.portico.lrc.compat.JFederationTimeAlreadyPassed: Time 11.0 has already passed
Handler: Received shutdown signal
Handler: Wait for federate to finish
Handler: Exit
at org.portico.impl.hla1516e.Rti1516eAmbassador.nextMessageRequestAvailable(Rti1516eAmbassador.java:4022)
at damageserver.Federate.start(Federate.java:217)
at damageserver.DamageServer.main(DamageServer.java:106)
Caused by: org.portico.lrc.compat.JFederationTimeAlreadyPassed: Time 11.0 has already passed
at org.portico.lrc.services.time.handlers.outgoing.TimeAdvanceRequestHandler.process(TimeAdvanceRequestHandler.java:73)
at org.portico.utils.messaging.MessageSink.process(MessageSink.java:187)
at org.portico.lrc.services.time.handlers.outgoing.NextEventRequestHandler.process(NextEventRequestHandler.java:81)
at org.portico.utils.messaging.MessageSink.process(MessageSink.java:187)
at org.portico.impl.hla1516e.Impl1516eHelper.processMessage(Impl1516eHelper.java:130)
at org.portico.impl.hla1516e.Rti1516eAmbassador.processMessage(Rti1516eAmbassador.java:5559)
at org.portico.impl.hla1516e.Rti1516eAmbassador.nextMessageRequestAvailable(Rti1516eAmbassador.java:3996)
... 2 more
C:\Users\bergtwvd\AppData\Local\NetBeans\Cache\8.1\executor-snippets\run.xml:53: Java returned: 1
BUILD FAILED (total time: 6 seconds)
LOGFILE 3
run:
DEBUG [main] portico.lrc: Creating new LRC
DEBUG [main] portico.lrc: Portico version: 2.1.0 (build 3)
DEBUG [main] portico.lrc: Interface: IEEE1516e
TRACE [main] portico.lrc: Provided connection implementation is "org.portico.bindings.jgroups.JGroupsConnection"
TRACE [main] portico.lrc: Trying to load connection class: org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: ATTEMPT create IConnection, class= class org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: SUCCESS created IConnection, class= class org.portico.bindings.jgroups.JGroupsConnection
TRACE [main] portico.lrc: Applying modules using component keyword: lrc1516e
TRACE [main] portico.lrc: STARTING Apply module [lrc1516-callback] to LRC
TRACE [main] portico.lrc: Applied [0/11] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc1516e-callback] to LRC
TRACE [main] portico.lrc: Applied [24/24] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc13-callback] to LRC
TRACE [main] portico.lrc: Applied [0/24] handlers
TRACE [main] portico.lrc: STARTING Apply module [lrc-base] to LRC
TRACE [main] portico.lrc: Applied [82/92] handlers
DEBUG [main] portico.lrc: Messaging framework configuration complete
INFO [main] portico.lrc: LRC initialized (HLA version: IEEE1516e)
INFO [main] portico.lrc: Opening LRC Connection
INFO [main] portico.lrc.jgroups: jgroups connection is up and running
HOME=C:\Users\bergtwvd\AppData\Local\Home
1::00:09:12.520::damageserver.DamageServer::main::federationName = TheWorld
1::00:09:12.520::damageserver.DamageServer::main::federateName = null
1::00:09:12.520::damageserver.DamageServer::main::connectAttempts = 0
1::00:09:12.520::damageserver.DamageServer::main::logFile = null
1::00:09:12.520::damageserver.DamageServer::main::logLevel = INFO
1::00:09:12.520::damageserver.Federate::connect::Attempt #1 ...
1::00:09:12.520::damageserver.Federate::connect::Connected to RTI
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml
TRACE [main] portico.lrc.merger: Beginning merge of 2 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
TRACE [main] portico.lrc.merger: -> Inserting class [HLAinteractionRoot.DamageReport]
TRACE [main] portico.lrc.merger: -> Inserting class [HLAinteractionRoot.DamageReport.EntityDamageReport]
DEBUG [main] portico.lrc: ATTEMPT Create federation execution [TheWorld]
TRACE [main] portico.lrc.jgroups: ATTEMPT Connecting to channel [TheWorld]
-------------------------------------------------------------------
GMS: address=PC-12505-53243, cluster=TheWorld, physical address=192.168.2.8:55991
-------------------------------------------------------------------
DEBUG [main] portico.lrc.jgroups: SUCCESS Connected to channel [TheWorld]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=0, source=PC-12505-53243
DEBUG [Regular] portico.lrc.jgroups: (GMS) findCoordinator(PC-12505-53243)
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=53683, source=PC-12505-37660
DEBUG [Regular] portico.lrc.jgroups: (GMS) setManifest(PC-12505-37660)
DEBUG [Regular] portico.lrc.jgroups: Received updated manifest from 27e911cd-2623-4cea-8691-2f5094016e76
DEBUG [Regular] portico.lrc.jgroups: Installed new manifest (follows)
DEBUG [Regular] portico.lrc.jgroups:
-----------------------------------
Manifest: channel=TheWorld
-----------------------------------
Version = 4
Local UUID = 2ea47764-9c3a-469d-8ba6-ab4e4e445078
Highest Handle = 2
Is Federation = true
Channel members: 2
(federate) id=1, name=TestFederate, uuid=27e911cd-2623-4cea-8691-2f5094016e76 **CO-ORDINATOR**
(application) id=2, uuid=2ea47764-9c3a-469d-8ba6-ab4e4e445078
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-37660
DEBUG [main] portico.lrc.jgroups: REQUEST createFederation: name=TheWorld
ERROR [main] portico.lrc.jgroups: FAILURE createFederation: already exists, name=TheWorld
1::00:09:16.389::damageserver.Federate::join::Didn't create federation, it already existed
DEBUG [main] portico.lrc: org.portico.lrc.compat.JFederationExecutionAlreadyExists: federation exists: TheWorld
DEBUG [main] portico.lrc: ATTEMPT Join federate [Federate-1476223752239] to federation [TheWorld]
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml
DEBUG [main] portico.lrc.fom: Parsing FED file (format=ieee1516e): file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml
DEBUG [main] portico.lrc: Parsed [2] additional FOM modules
DEBUG [main] portico.lrc.jgroups: Validate that [2] modules can merge successfully with the existing FOM
TRACE [main] portico.lrc.merger: Beginning merge of 3 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml] into combined FOM
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
DEBUG [main] portico.lrc.jgroups: Modules can be merged successfully, continue with join
DEBUG [main] portico.lrc.jgroups: REQUEST joinFederation: federate=Federate-1476223752239, federation=TheWorld
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=22, source=PC-12505-53243
DEBUG [Regular] portico.lrc.jgroups: (GMS) joinFederation(PC-12505-53243)
DEBUG [Regular] portico.lrc.jgroups: Received federate join notification: federate=Federate-1476223752239, federation=TheWorld, source=2ea47764-9c3a-469d-8ba6-ab4e4e445078
INFO [Regular] portico.lrc.jgroups: Federate [Federate-1476223752239] joined federation [TheWorld]
INFO [main] portico.lrc.jgroups: SUCCESS Joined federation with name=Federate-1476223752239
DEBUG [main] portico.lrc.jgroups: Merging 2 additional FOM modules that we receive with join request
TRACE [main] portico.lrc.merger: Beginning merge of 3 FOM models
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/RPR_FOM_v2.0_1516-2010.xml] into combined FOM
TRACE [main] portico.lrc.merger: Merging [file:/C:/Users/bergtwvd/msaas-A/services/DamageServer/foms/Damage.xml] into combined FOM
TRACE [main] portico.lrc: Created Mom.Federation object, added to Repository (undiscovered)
TRACE [main] portico.lrc: Created Mom.Federate(Federate-1476223752239), queued discovery notification
TRACE [main] portico.lrc: joined federation, waiting for RoleCalls from [1, 2]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=47828, source=PC-12505-53243
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=55670, source=PC-12505-37660
DEBUG [Regular] portico.lrc: @REMOTE RoleCall received [handle:1,name:TestFederate] by local federate [Federate-1476223752239]
TRACE [Regular] portico.lrc: Created Mom.Federate(TestFederate), queued discovery notification
DEBUG [Regular] portico.lrc: (RoleCall) Adding undiscoverd instance [2] following RoleCall notification
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=567, source=PC-12505-53243
INFO [main] portico.lrc: SUCCESS Joined federate [Federate-1476223752239] to federation [TheWorld]: handle=2
1::00:09:16.749::damageserver.Federate::join::Joined Federation
DEBUG [main] portico.lrc: REQUEST Enable asynchronous delivery for [Federate-1476223752239]
1::00:09:16.749::damageserver.Federate::enableTimePolicy::Enable time policy
DEBUG [main] portico.lrc: SUCCESS Enabled asynchronous delivery for [Federate-1476223752239]
DEBUG [main] portico.lrc: REQUEST Enable time constrained for [Federate-1476223752239]
INFO [main] portico.lrc: PENDING Enable time constrained PENDING for [Federate-1476223752239]
TRACE [main] portico.lrc: @REMOTE Received MOM object discovery for federate [MOM.Federate(Federate-1476223752239)]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=2097151
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=214, source=PC-12505-53243
TRACE [main] portico.lrc: @REMOTE Received MOM object discovery for federate [MOM.Federate(TestFederate)]
DEBUG [main] portico.lrc: DISCARD Discovery of object (not subscribed): object=1
DEBUG [main] portico.lrc: @REMOTE Federate [Federate-1476223752239] requests ENABLE time constrained
1::00:09:16.749::damageserver.FederateAmbassador::timeConstrainedEnabled::timeConstrainedEnabled Time=0.0
INFO [main] portico.lrc: ENABLED time constrained for [Federate-1476223752239]
TRACE [main] portico.lrc: CALLBACK timeConstrainedEnabled(time=0.0)
TRACE [main] portico.lrc: timeConstrainedEnabled() callback complete
DEBUG [main] portico.lrc: REQUEST Enable time regulation for [Federate-1476223752239]: fedtime=0.0, lookahead=0.1
INFO [main] portico.lrc: PENDING Enable time regulation PENDING for [Federate-1476223752239]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=256, source=PC-12505-53243
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-37660
DEBUG [main] portico.lrc: @REMOTE Federate [Federate-1476223752239] requests ENABLE time regulation (fedtime=0.0, lookahead=0.1)
DEBUG [main] portico.lrc: ENABLED time regulating for [Federate-1476223752239] (fedtime=10.9)
1::00:09:17.764::damageserver.FederateAmbassador::timeRegulationEnabled::timeRegulationEnabled Time=10.9
TRACE [main] portico.lrc: CALLBACK timeRegulationEnabled(time=10.9)
TRACE [main] portico.lrc: timeRegulationEnabled() callback complete
1::00:09:17.764::damageserver.Federate::enableTimePolicy::Time policy enabled
DEBUG [main] portico.lrc: ATTEMPT Subscribe to [789] with attributes [788, 784]
DEBUG [main] portico.lrc: Queued Discover callback for instance [2] after subscription to class [789]
INFO [main] portico.lrc: SUCCESS Subscribeed to [789] with attributes [788, 784]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=433, source=PC-12505-53243
DEBUG [main] portico.lrc: ATTEMPT Subscribe to interaction class [1070]
INFO [main] portico.lrc: SUCCESS Subscribed to interaction class [1070]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=267, source=PC-12505-53243
DEBUG [main] portico.lrc: ATTEMPT Publish interaction class [504]
INFO [main] portico.lrc: SUCCESS Published interaction class [504]
1::00:09:17.780::damageserver.Federate::publishAndSubscribe::Published and Subscribed
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=236, source=PC-12505-53243
1::00:09:17.780::damageserver.Federate::start::Start ...
DEBUG [main] portico.lrc: REQUEST Next event request for [Federate-1476223752239]: time=1.7976931348623157E308
1::00:09:17.780::damageserver.Federate::start::nextMessageRequest
DEBUG [main] portico.lrc: REQUEST Time advance request for [Federate-1476223752239] to [11.0]
INFO [main] portico.lrc: PENDING Requested time advance for [Federate-1476223752239] to [11.0], waiting for grant...
DEBUG [main] portico.lrc: Federate [TestFederate] requests ADVANCE to time [11.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [TestFederate] to time [11.0]
DEBUG [main] portico.lrc: ADVANCE (QUEUED) time-advance grant for federate [Federate-1476223752239] to time [11.0]
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-53243
1::00:09:17.780::damageserver.FederateAmbassador::discoverObjectInstance::discoverObjectInstance name=HLA2
DEBUG [main] portico.lrc: @REMOTE Discover object: owner=TestFederate, object=2, class=789, owned=[1242, 804, 803, 788, 784]
INFO [main] portico.lrc: DISCOVER object [2] registeredAs=789, discoveredAs=789
TRACE [main] portico.lrc: CALLBACK discoverObjectInstance(object=2,class=789,name=HLA2)
TRACE [main] portico.lrc: discoverObjectInstance() callback complete
DEBUG [main] portico.lrc: ATTEMPT Request update of object [2] for attributes=[788, 784]
INFO [main] portico.lrc: SUCCESS Requested update of object [2] for attributes=[788, 784]
DEBUG [main] portico.lrc: Federate [Federate-1476223752239] requests ADVANCE to time [11.0]
DEBUG [main] portico.lrc: @REMOTE Received object UPDATE [2] with attributes [788, 784] @11.0
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=412, source=PC-12505-53243
TRACE [main] portico.lrc: CALLBACK reflectAttributeValues(object=2,attributes={788(8b),784(50b)},time=11.0) (TSO)
1::00:09:17.795::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues: sentOrdering=TIMESTAMP receivedOrdering=TIMESTAMP time=11.0
1::00:09:17.795::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues for name=HLA2
1::00:09:17.795::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues ET=(1.2.3.4.5.6.0)
TRACE [main] portico.lrc: reflectAttributeValues() callback complete
DEBUG [main] portico.lrc: @REMOTE Request object update: object=2, attributes=[788, 784], sourceFederate=Federate-1476223752239
DEBUG [main] portico.lrc: (veto) don't own any attributes
DEBUG [main] portico.lrc: @REMOTE Received INTERACTION [1070] with parameters [1081, 1073] @11.0
TRACE [main] portico.lrc: CALLBACK receiveInteraction(class=1070,parameters={1081(7b),1073(24b)},time=11.0) (TSO)
TRACE [main] portico.lrc: receiveInteraction() callback complete
DEBUG [main] portico.lrc: ADVANCE (GRANTED) for federate [Federate-1476223752239] to time [11.0]
TRACE [main] portico.lrc: CALLBACK timeAdvanceGrant(time=11.0)
TRACE [main] portico.lrc: timeAdvanceGrant() callback complete
1::00:09:17.811::damageserver.FederateAmbassador::reflectAttributeValues::reflectAttributeValues SV=(DRM_FPW;w=(x=3934855.8260064786;y=836358.1693870248;z=4934322.5433315);f=false;o=(psi=0.0;theta=0.0;phi=0.0);v=(x=10.0;y=0.0;z=0.0))
1::00:09:17.811::damageserver.FederateAmbassador::receiveInteraction::receiveInteraction: sentOrdering=TIMESTAMP receivedOrdering=TIMESTAMP time=11.0
1::00:09:17.811::damageserver.FederateAmbassador::createMunitionDetonationInteraction::FiringObjectIdentifier: ME!
DEBUG [main] portico.lrc: ATTEMPT Send interaction [504] with parameters [508, 505, 506] @11.1
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=97, source=PC-12505-53243
1::00:09:17.811::damageserver.FederateAmbassador::createMunitionDetonationInteraction::DetonationLocation: (x=10.0;y=11.0;z=12.0)
INFO [main] portico.lrc: SUCCESS Sent interaction [504] with parameters [508, 505, 506] @11.1
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=107, source=PC-12505-37660
1::00:09:17.811::damageserver.FederateAmbassador::receiveInteraction::TSO
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=84, source=PC-12505-37660
TRACE [Regular] portico.lrc.jgroups: (incoming) asynchronous, channel=TheWorld, size=243, source=PC-12505-37660
1::00:09:17.811::damageserver.FederateAmbassador::timeAdvanceGrant::timeAdvanceGrant Time=11.0
DEBUG [main] portico.lrc: REQUEST Next event request for [Federate-1476223752239]: time=1.7976931348623157E308
1::00:09:17.827::damageserver.Federate::sendDamageReport::queryLITS=11.0
DEBUG [main] portico.lrc: REQUEST Time advance request for [Federate-1476223752239] to [11.0]
1::00:09:17.827::damageserver.Federate::sendDamageReport::queryLogicalTime=11.0
DEBUG [main] portico.lrc: org.portico.lrc.compat.JFederationTimeAlreadyPassed: Time 11.0 has already passed
1::00:09:17.827::damageserver.Federate::sendDamageReport::sendDamageReport at time=11.1
Handler: Received shutdown signal
Handler: Wait for federate to finish
Handler: Exit
Exception in thread "main" hla.rti1516e.exceptions.LogicalTimeAlreadyPassed: org.portico.lrc.compat.JFederationTimeAlreadyPassed: Time 11.0 has already passed
at org.portico.impl.hla1516e.Rti1516eAmbassador.nextMessageRequest(Rti1516eAmbassador.java:3940)
at damageserver.Federate.start(Federate.java:218)
at damageserver.DamageServer.main(DamageServer.java:106)
Caused by: org.portico.lrc.compat.JFederationTimeAlreadyPassed: Time 11.0 has already passed
at org.portico.lrc.services.time.handlers.outgoing.TimeAdvanceRequestHandler.process(TimeAdvanceRequestHandler.java:73)
at org.portico.utils.messaging.MessageSink.process(MessageSink.java:187)
at org.portico.lrc.services.time.handlers.outgoing.NextEventRequestHandler.process(NextEventRequestHandler.java:81)
at org.portico.utils.messaging.MessageSink.process(MessageSink.java:187)
at org.portico.impl.hla1516e.Impl1516eHelper.processMessage(Impl1516eHelper.java:130)
at org.portico.impl.hla1516e.Rti1516eAmbassador.processMessage(Rti1516eAmbassador.java:5559)
at org.portico.impl.hla1516e.Rti1516eAmbassador.nextMessageRequest(Rti1516eAmbassador.java:3914)
... 2 more
C:\Users\bergtwvd\AppData\Local\NetBeans\Cache\8.1\executor-snippets\run.xml:53: Java returned: 1
BUILD FAILED (total time: 6 seconds)
Issue with using NMRA.
Federate A is regulating/constrained, with lookahead 0. Uses NMRA. Federate B is timestepped, uses TAR.
TEST CASE 1
Federate A:
Federate B:
Observations for A:
See logfile 1 below.
TEST CASE 2
Federate A is adapted to send the interaction timestamped with T+1 (by adding 1 to the time in the send call).
Sending the interaction with timestamp lbts, T+5 or T+10 yields the same error.
See logfile 2 below.
TEST CASE 3
Similar to test case 2: NMRA is changed to NMR, using a lookahead of 0.1. I.e. enableTimeRegulation with LA=0.1. Send interaction with timestamp is current time+LA.
Get same error, see logfile 3 below.
Note that in the logs the messages from Portico and from the application Logger are mixed. For each one the order is correct, but not the timing of print on the console.
LOGFILE 1
LOGFILE 2
LOGFILE 3