Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Jump to bottom

Federated execution without deadlines fail in actually distributed environments #2034

Closed
Jakio815 opened this issue Oct 2, 2023 · 7 comments
Closed

Federated execution without deadlines fail in actually distributed environments #2034

Jakio815 opened this issue Oct 2, 2023 · 7 comments
Labels
bug Something isn't working federated

Comments

@Jakio815
Copy link
Collaborator

Jakio815 commented Oct 2, 2023

The federated execution works well on local machines, running all processes on one machine.

However, if there are no deadlines, it fails in actually distributed environments.

I've made an experiment running SimpleFederated.lf on a Ubuntu RTI server, and two Raspberry Pis.

The SimpleFederated.lf looks like this, and is in test/C/src/federated/SimpleFederatedAuthenticated.lf

target C {
  timeout: 2 secs,
  build-type: RelWithDebInfo
}

reactor Fed {
  input in: int
  output out: int
}

federated reactor {
  fed1 = new Fed()
  fed2 = new Fed()

  fed1.out -> fed2.in
  fed2.out -> fed1.in
}

It does not have any deadlines, but only timeouts, and fails.
@Jakio815 Jakio815 added bug Something isn't working federated labels Oct 2, 2023
@edwardalee
Copy link
Collaborator

How exactly does it fail? (The test is hard to replicate).

@Jakio815
Copy link
Collaborator Author

Jakio815 commented Oct 3, 2023

I'll leave the logs.

The debug messages are too much, so I kind of cut off the middle part. Sorry for the readability.

RTI DEBUG logs.

dongha@dongha-17Z95N-GP7NL:~$ RTI  -n 2
RTI: Number of federates: 2
Starting RTI for 2 federates in federation ID Unidentified Federation.
RTI using TCP port 15045 for federation Unidentified Federation.
RTI: Listening for federates.
DEBUG: RTI received federate ID: 0.
DEBUG: RTI received federation ID: Unidentified Federation.
DEBUG: RTI got address 192.168.0.7 from federate 0.
DEBUG: RTI responding with MSG_TYPE_ACK to federate 0.
DEBUG: RTI waiting for MSG_TYPE_NEIGHBOR_STRUCTURE from federate 0.
DEBUG: RTI got 1 upstreams and 1 downstreams from federate 0.
DEBUG: RTI waiting for MSG_TYPE_UDP_PORT from federate 0.
DEBUG: RTI got MSG_TYPE_UDP_PORT 0 from federate 0.
DEBUG: Physical time: 1696297545060723168. Elapsed: -7527074491794052640. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545060723168 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545068118403. Elapsed: -7527074491786657405. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545068118403 to federate 0.
DEBUG: Physical time: 1696297545068168565. Elapsed: -7527074491786607243. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545068168565 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545124209502. Elapsed: -7527074491730566306. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545124209502 to federate 0.
DEBUG: Physical time: 1696297545124272843. Elapsed: -7527074491730502965. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545124272843 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545173259421. Elapsed: -7527074491681516387. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545173259421 to federate 0.
DEBUG: Physical time: 1696297545173320027. Elapsed: -7527074491681455781. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545173320027 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545228318137. Elapsed: -7527074491626457671. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545228318137 to federate 0.
DEBUG: Physical time: 1696297545228378683. Elapsed: -7527074491626397125. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545228378683 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545291655269. Elapsed: -7527074491563120539. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545291655269 to federate 0.
DEBUG: Physical time: 1696297545291717375. Elapsed: -7527074491563058433. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545291717375 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545340514389. Elapsed: -7527074491514261419. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545340514389 to federate 0.
DEBUG: Physical time: 1696297545340565402. Elapsed: -7527074491514210406. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545340565402 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545393354196. Elapsed: -7527074491461421612. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545393354196 to federate 0.
DEBUG: Physical time: 1696297545393414842. Elapsed: -7527074491461360966. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545393414842 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545449376579. Elapsed: -7527074491405399229. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545449376579 to federate 0.
DEBUG: Physical time: 1696297545449449214. Elapsed: -7527074491405326594. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545449449214 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545503230251. Elapsed: -7527074491351545557. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545503230251 to federate 0.
DEBUG: Physical time: 1696297545503290594. Elapsed: -7527074491351485214. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545503290594 to federate 0.
DEBUG: RTI received T3 clock sync message from federate 0.
DEBUG: Physical time: 1696297545554361620. Elapsed: -7527074491300414188. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545554361620 to federate 0.
DEBUG: RTI finished initial clock synchronization with federate 0.
DEBUG: RTI received federate ID: 1.
DEBUG: RTI received federation ID: Unidentified Federation.
DEBUG: RTI got address 192.168.0.9 from federate 1.
DEBUG: RTI responding with MSG_TYPE_ACK to federate 1.
DEBUG: RTI waiting for MSG_TYPE_NEIGHBOR_STRUCTURE from federate 1.
DEBUG: RTI got 1 upstreams and 1 downstreams from federate 1.
DEBUG: RTI waiting for MSG_TYPE_UDP_PORT from federate 1.
DEBUG: RTI: Received message type 2 from federate 0.
DEBUG: RTI received timestamp message with time: 1696297545535824406.
DEBUG: RTI got MSG_TYPE_UDP_PORT 0 from federate 1.
DEBUG: Physical time: 1696297545569753865. Elapsed: -7527074491285021943. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545569753865 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545579969710. Elapsed: -7527074491274806098. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545579969710 to federate 1.
DEBUG: Physical time: 1696297545580023661. Elapsed: -7527074491274752147. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545580023661 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545636374137. Elapsed: -7527074491218401671. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545636374137 to federate 1.
DEBUG: Physical time: 1696297545636425958. Elapsed: -7527074491218349850. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545636425958 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545690346682. Elapsed: -7527074491164429126. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545690346682 to federate 1.
DEBUG: Physical time: 1696297545690407818. Elapsed: -7527074491164367990. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545690407818 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545742172999. Elapsed: -7527074491112602809. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545742172999 to federate 1.
DEBUG: Physical time: 1696297545742232151. Elapsed: -7527074491112543657. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545742232151 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545798258977. Elapsed: -7527074491056516831. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545798258977 to federate 1.
DEBUG: Physical time: 1696297545798320066. Elapsed: -7527074491056455742. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545798320066 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545846981004. Elapsed: -7527074491007794804. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545846981004 to federate 1.
DEBUG: Physical time: 1696297545847034635. Elapsed: -7527074491007741173. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545847034635 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545900746661. Elapsed: -7527074490954029147. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545900746661 to federate 1.
DEBUG: Physical time: 1696297545900806284. Elapsed: -7527074490953969524. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545900806284 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297545961404825. Elapsed: -7527074490893370983. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545961404825 to federate 1.
DEBUG: Physical time: 1696297545961464585. Elapsed: -7527074490893311223. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297545961464585 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297546009379981. Elapsed: -7527074490845395827. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297546009379981 to federate 1.
DEBUG: Physical time: 1696297546009458144. Elapsed: -7527074490845317664. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 19.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297546009458144 to federate 1.
DEBUG: RTI received T3 clock sync message from federate 1.
DEBUG: Physical time: 1696297546058569107. Elapsed: -7527074490796206701. Offset: 0
DEBUG: Clock sync:  RTI sending TCP message type 21.
DEBUG: Clock sync: RTI sent PHYSICAL_TIME_SYNC_MESSAGE with timestamp 1696297546058569107 to federate 1.
DEBUG: RTI finished initial clock synchronization with federate 1.
DEBUG: All federates have connected to RTI.
RTI: All expected federates have connected. Starting execution.
RTI: Waiting for thread handling federate 0.
DEBUG: RTI: Received message type 2 from federate 1.
DEBUG: RTI received timestamp message with time: 1696297546042146311.
LOG: RTI sent start time 1696297547042146311 to federate 1.
LOG: RTI sent start time 1696297547042146311 to federate 0.
DEBUG: RTI: Received message type 4 from federate 1.
Federate 1 has resigned.
LOG: Minimum upstream LTC for federate/enclave 0 is (7527074489812629496, 4294967295)(adjusted by after delay).
LOG: RTI sent to federate 0 the tag advance grant (TAG) (7527074489812629496, 4294967295).
DEBUG: RTI: Received message type 6 from federate 0.
LOG: RTI received from federate 0 the Next Event Tag (NET) (0, 0)
DEBUG: RTI: Updated the recorded next event tag for federate/enclave 0 to (0, 0)
LOG: Minimum upstream LTC for federate/enclave 0 is (7527074489812629496, 4294967295)(adjusted by after delay).
DEBUG: NOTE: FOREVER is displayed as (7527074489812629496, 4294967295) and NEVER as (7527074489812629497, 0)
LOG: Earliest next event upstream has tag (7527074489812629496, 4294967295).
DEBUG: -9223372036854775808 < 9223372036854775807
LOG: Minimum upstream LTC for federate/enclave 1 is (7527074489812629497, 0)(adjusted by after delay).
DEBUG: NOTE: FOREVER is displayed as (7527074489812629496, 4294967295) and NEVER as (7527074489812629497, 0)
DEBUG: Earliest next event upstream of fed/encl 1 at fed/encl 0 has tag (0, 0).
DEBUG: 1696297547042146311 < 9223372036854775807
DEBUG: 1696297547042146311 < 9223372036854775807
LOG: Earliest next event upstream has tag (0, 0).
DEBUG: 1696297547042146311 < 9223372036854775807
DEBUG: 1696297547042146311 < 9223372036854775807
DEBUG: RTI: Received message type 23 from federate 0.
WARNING: RTI: Destination federate 1 is no longer connected. Dropping message.
LOG: Fed status: next_event (7527074489812629496, -1), completed (7527074489812629497, 0), last_granted (7527074489812629497, 0), last_provisionally_granted (7527074489812629497, 0).
DEBUG: RTI: Received message type 9 from federate 0.
LOG: RTI received from federate/enclave 0 the Logical Tag Complete (LTC) (0, 0).
DEBUG: 1696297547042146311 < 9223372036854775807
LOG: Minimum upstream LTC for federate/enclave 1 is (0, 0)(adjusted by after delay).
DEBUG: 1696297547042146311 < 9223372036854775807
DEBUG: NOTE: FOREVER is displayed as (7527074489812629496, 4294967295) and NEVER as (7527074489812629497, 0)
DEBUG: Earliest next event upstream of fed/encl 1 at fed/encl 0 has tag (0, 0).
DEBUG: 1696297547042146311 < 9223372036854775807
DEBUG: 1696297547042146311 < 9223372036854775807
LOG: Earliest next event upstream has tag (0, 0).
DEBUG: 1696297547042146311 < 9223372036854775807
DEBUG: 1696297547042146311 < 9223372036854775807
LOG: Minimum upstream LTC for federate/enclave 0 is (7527074489812629496, 4294967295)(adjusted by after delay).
DEBUG: NOTE: FOREVER is displayed as (7527074489812629496, 4294967295) and NEVER as (7527074489812629497, 0)
LOG: Earliest next event upstream has tag (7527074489812629496, 4294967295).
DEBUG: RTI: Received message type 4 from federate 0.
Federate 0 has resigned.
LOG: Minimum upstream LTC for federate/enclave 1 is (7527074489812629496, 4294967295)(adjusted by after delay).
RTI: Federate 0 thread exited.
RTI: Waiting for thread handling federate 1.
RTI: Federate 1 thread exited.
RTI is exiting.
RTI is exiting.

federate0.log

dongha0@raspberrypi:~/lingua-franca $ ./test/C/fed-gen/SimpleFederated/bin/federate__fed1
DEBUG: Physical time: 1019856111. Elapsed: -9223372035834919697. Offset: 0
DEBUG: Start time: 1019856111ns
---- Start execution at time Wed Dec 31 17:00:01 1969
---- plus 19856111 nanoseconds
DEBUG: _lf_new_token: Allocated memory for token: 0xd4d0e0
DEBUG: Scheduler: Initializing with 1 workers
DEBUG: Scheduler: Max reaction level: 4
DEBUG: Scheduler: Initialized vector of reactions for level 0 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 1 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 2 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 3 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 4 with size 1
Federate 0: LOG: Connecting to the RTI.
Federate 0: Successfully connected to RTI.
Federate 0: LOG: Connected to an RTI. Sending federation ID for authentication.
Federate 0: DEBUG: Waiting for response to federation ID from the RTI.
Federate 0: LOG: Received acknowledgment from the RTI.
Federate 0: Connected to RTI at 192.168.0.6:15045.
Federate 0: DEBUG: Waiting for initial clock synchronization messages from the RTI.
Federate 0: DEBUG: Physical time: 1082870067. Elapsed: 63013956. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545060723168 from RTI at local time 1082870067.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1083008736. Elapsed: 63152625. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545068118403 from RTI at local time 1082870067. (difference -1696297543985248336)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543981481384.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754398148138.
Federate 0: DEBUG: Physical time: 1141900262. Elapsed: 122044151. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545068168565 from RTI at local time 1141900262.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1142026302. Elapsed: 122170191. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545124209502 from RTI at local time 1141900262. (difference -1696297543982309240)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543954225751.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395422575.
Federate 0: DEBUG: Physical time: 1190988954. Elapsed: 171132843. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545124272843 from RTI at local time 1190988954.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1191134864. Elapsed: 171278753. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545173259421 from RTI at local time 1190988954. (difference -1696297543982270467)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543957704223.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395770422.
Federate 0: DEBUG: Physical time: 1244543823. Elapsed: 224687712. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545173320027 from RTI at local time 1244543823.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1244671289. Elapsed: 224815178. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545228318137 from RTI at local time 1244543823. (difference -1696297543983774314)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543956211526.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395621152.
Federate 0: DEBUG: Physical time: 1298557423. Elapsed: 278701312. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545228378683 from RTI at local time 1298557423.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1298682389. Elapsed: 278826278. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545291655269 from RTI at local time 1298557423. (difference -1696297543993097846)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543961397070.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754396139707.
Federate 0: DEBUG: Physical time: 1358020035. Elapsed: 338163924. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545291717375 from RTI at local time 1358020035.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1358145222. Elapsed: 338289111. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545340514389 from RTI at local time 1358020035. (difference -1696297543982494354)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543958033253.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395803325.
Federate 0: DEBUG: Physical time: 1408048596. Elapsed: 388192485. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545340565402 from RTI at local time 1408048596.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1408169117. Elapsed: 388313006. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545393354196 from RTI at local time 1408048596. (difference -1696297543985305600)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543958850942.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395885094.
Federate 0: DEBUG: Physical time: 1462025992. Elapsed: 442169881. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545393414842 from RTI at local time 1462025992.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1462150605. Elapsed: 442294494. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545449376579 from RTI at local time 1462025992. (difference -1696297543987350587)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543959307412.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395930741.
Federate 0: DEBUG: Physical time: 1517744883. Elapsed: 497888772. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545449449214 from RTI at local time 1517744883.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1517864404. Elapsed: 498008293. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545503230251 from RTI at local time 1517744883. (difference -1696297543985485368)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543958535089.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395853508.
Federate 0: DEBUG: Physical time: 1571735409. Elapsed: 551879298. Offset: 0
Federate 0: DEBUG: Received T1 message with time payload 1696297545503290594 from RTI at local time 1571735409.
Federate 0: DEBUG: Sending T3 message to RTI.
Federate 0: DEBUG: Physical time: 1571857097. Elapsed: 552000986. Offset: 0
Federate 0: DEBUG: Clock sync: Received T4 message with time payload 1696297545554361620 from RTI at local time 1571735409. (difference -1696297543982626211)
Federate 0: DEBUG: Clock sync: Estimated clock error: 1696297543957029854.
Federate 0: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395702985.
Federate 0: LOG: Clock sync: New offset: 1696297543960277647. Round trip delay to RTI (now): 50949338. (AVG): 0. (SD): 0. Local round trip delay: 121688. Test offset: 0.
Federate 0: LOG: Finished initial clock synchronization with the RTI.
Federate 0: DEBUG: Scheduler: Initializing with 1 workers
Federate 0: DEBUG: Scheduler: Enqueueing reaction federate__fed1.ns_federate__fed2 reaction 0, which has level 0.
Federate 0: DEBUG: Scheduler: Trying to lock the mutex for level 0.
Federate 0: DEBUG: Scheduler: Locked the mutex for level 0.
Federate 0: DEBUG: Scheduler: Accessing triggered reactions at the level 0 with index 0.
Federate 0: DEBUG: Scheduler: Index for level 0 is at 0.
Federate 0: DEBUG: Scheduler: Enqueueing reaction federate__fed1.nr_federate__fed1 reaction 0, which has level 3.
Federate 0: DEBUG: Scheduler: Accessing triggered reactions at the level 3 with index 0.
Federate 0: DEBUG: Scheduler: Index for level 3 is at 0.
Federate 0: DEBUG: Resetting port status fields.
Federate 0: DEBUG: last_TAG=-9223372036854775808
Federate 0: DEBUG: Updated MLAA to 4 at time 0 with 1 items in zero-delay action table.
Federate 0: DEBUG: Synchronizing with other federates.
Federate 0: DEBUG: Physical time: 1696297545535824406. Elapsed: 1696297544515968295. Offset: 1696297543960277647
Federate 0: DEBUG: Sending time 1696297545535824406 to the RTI.
Federate 0: DEBUG: Read 9 bytes.
Federate 0: Starting timestamp is: 1696297547042146311.
Federate 0: DEBUG: Physical time: 1696297546045969556. Elapsed: 1696297545026113445. Offset: 1696297543960277647
Federate 0: LOG: Current physical time is: 1696297546045969556.
Federate 0: DEBUG: 1696297547042146311 < 1696297549042146311
Federate 0: LOG: Waiting for start time 1696297547042146311 plus STA 0.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 0: DEBUG: Physical time: 1696297546046244357. Elapsed: -995901954. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Clock offset is 1696297543960277647 ns.
Federate 0: DEBUG: -------- Waiting 995901954 ns for physical time to match logical time 0.
Federate 0: DEBUG: -------- wait_until interrupted before timeout.
Federate 0: DEBUG: Physical time: 1696297546046298803. Elapsed: -995847508. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Returned from wait, having waited 54446 ns.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 0: DEBUG: Physical time: 1696297546046336396. Elapsed: -995809915. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Clock offset is 1696297543960277647 ns.
Federate 0: DEBUG: -------- Waiting 10099675 ns for physical time to match logical time 0.
Federate 0: DEBUG: -------- wait_until interrupted before timeout.
Federate 0: DEBUG: Physical time: 1696297547032094211. Elapsed: -10052100. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Returned from wait, having waited 47575 ns.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 0: DEBUG: Physical time: 1696297547032130638. Elapsed: -10015673. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Clock offset is 1696297543960277647 ns.
Federate 0: DEBUG: -------- Waiting 10015673 ns for physical time to match logical time 0.
Federate 0: DEBUG: -------- wait_until interrupted before timeout.
Federate 0: DEBUG: Physical time: 1696297547032178065. Elapsed: -9968246. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Returned from wait, having waited 47427 ns.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 0: DEBUG: Physical time: 1696297547065716271. Elapsed: 23569960. Offset: 1696297543960277647
Federate 0: DEBUG: Wait time -23569960 is less than MIN_SLEEP_DURATION 10000. Skipping wait.
Federate 0: DEBUG: Done waiting for start time 1696297547042146311.
Federate 0: DEBUG: Physical time: 1696297547065771939. Elapsed: 23625628. Offset: 1696297543960277647
Federate 0: DEBUG: Physical time is ahead of current time by 23625628. This should be small.
Federate 0: DEBUG: -9223372036854775808 < 1696297547042146311
Federate 0: DEBUG: Checking NET to see whether it should be bounded by physical time. Min delay from physical action: -9223372036854775808.
Federate 0: DEBUG: Sending tag (0, 0) to the RTI.
Federate 0: LOG: Sent next event tag (NET) (0, 0) to RTI.
Federate 0: DEBUG: Waiting for a TAG from the RTI.
Federate 0: DEBUG: In update_last_known_status_on_input ports.
Federate 0: DEBUG: Updating the last known status tag of port 0 from (-1696297547042146311, 0) to (7527074489812629496, 4294967295).
Federate 0: DEBUG: last_TAG=9223372036854775807
Federate 0: DEBUG: 1696297547042146311 < 9223372036854775807
Federate 0: DEBUG: Updated MLAA to 2147483647 at time 0 with last_TAG=9223372036854775807 and current time 1696297547042146311.
Federate 0: LOG: Received Time Advance Grant (TAG): (7527074489812629496, 4294967295).
Federate 0: Environment 0: ---- Spawning 1 workers.
Federate 0: LOG: Starting 1 worker threads in environment
Federate 0: LOG: Worker thread 0 started.
Federate 0: DEBUG: Trying to acquire the global mutex.
Federate 0: DEBUG: Waiting on MLAA with next_reaction_level 0 and MLAA 2147483647.
Federate 0: DEBUG: Exiting wait with MLAA 2147483647 and next_reaction_level 0.
Federate 0: DEBUG: Scheduler: Worker 0 popping reaction with level 0, index for level: 0.
Federate 0: DEBUG: Worker 0: Got from scheduler reaction federate__fed1.ns_federate__fed2 reaction 0: level: 0, is input reaction: 0, chain ID: 1, and deadline -9223372036854775808.
Federate 0: LOG: Worker 0: Invoking reaction federate__fed1.ns_federate__fed2 reaction 0 at elapsed tag (0, 0).
Federate 0: DEBUG: Adding network port absent reaction to table.
Federate 0: DEBUG: Added network output control reaction to table. Enqueueing it...
Federate 0: DEBUG: Enqueueing port absent reactions at time 0.
Federate 0: DEBUG: Inserting port absent reaction on reaction queue.
Federate 0: DEBUG: Scheduler: Enqueueing reaction federate__fed1.ns_federate__fed2 reaction 2, which has level 2.
Federate 0: DEBUG: Scheduler: Accessing triggered reactions at the level 2 with index 0.
Federate 0: DEBUG: Scheduler: Index for level 2 is at 0.
Federate 0: DEBUG: There are 0 outputs from reaction federate__fed1.ns_federate__fed2 reaction 0.
Federate 0: DEBUG: Worker 0: Done with reaction federate__fed1.ns_federate__fed2 reaction 0.
Federate 0: DEBUG: Worker 0 is out of ready reactions.
Federate 0: DEBUG: Scheduler: Worker 0 is the last idle thread.
Federate 0: DEBUG: Waiting with curr_reaction_level 1.
Federate 0: DEBUG: Trying to acquire the global mutex.
Federate 0: DEBUG: Waiting on MLAA with next_reaction_level 1 and MLAA 2147483647.
Federate 0: DEBUG: Exiting wait with MLAA 2147483647 and next_reaction_level 1.
Federate 0: DEBUG: DEBUG: start of rxn queue at 1 is (nil)
Federate 0: DEBUG: Waiting with curr_reaction_level 2.
Federate 0: DEBUG: Trying to acquire the global mutex.
Federate 0: DEBUG: Waiting on MLAA with next_reaction_level 2 and MLAA 2147483647.
Federate 0: DEBUG: Exiting wait with MLAA 2147483647 and next_reaction_level 2.
Federate 0: DEBUG: DEBUG: start of rxn queue at 2 is 0xd4cc90
Federate 0: DEBUG: Scheduler: Notifying 1 workers.
Federate 0: DEBUG: Scheduler: New number of idle workers: 0.
Federate 0: DEBUG: Scheduler: Worker 0 popping reaction with level 2, index for level: 0.
Federate 0: DEBUG: Worker 0: Got from scheduler reaction federate__fed1.ns_federate__fed2 reaction 2: level: 2, is input reaction: 0, chain ID: 1, and deadline -9223372036854775808.
Federate 0: LOG: Worker 0: Invoking reaction federate__fed1.ns_federate__fed2 reaction 2 at elapsed tag (0, 0).
Federate 0: LOG: Executing port absent reaction for port 0 to federate 1 at time 0.
Federate 0: LOG: The output port is NULL or it is not present.
Federate 0: LOG: Sending port absent for tag (0, 0) for port 0 to federate 1.
Federate 0: DEBUG: There are 0 outputs from reaction federate__fed1.ns_federate__fed2 reaction 2.
Federate 0: DEBUG: Worker 0: Done with reaction federate__fed1.ns_federate__fed2 reaction 2.
Federate 0: DEBUG: Worker 0 is out of ready reactions.
Federate 0: DEBUG: Scheduler: Worker 0 is the last idle thread.
Federate 0: DEBUG: Waiting with curr_reaction_level 3.
Federate 0: DEBUG: Trying to acquire the global mutex.
Federate 0: DEBUG: Waiting on MLAA with next_reaction_level 3 and MLAA 2147483647.
Federate 0: DEBUG: Exiting wait with MLAA 2147483647 and next_reaction_level 3.
Federate 0: DEBUG: DEBUG: start of rxn queue at 3 is 0xd4cea0
Federate 0: DEBUG: Scheduler: Notifying 1 workers.
Federate 0: DEBUG: Scheduler: New number of idle workers: 0.
Federate 0: DEBUG: Scheduler: Worker 0 popping reaction with level 3, index for level: 0.
Federate 0: DEBUG: Worker 0: Got from scheduler reaction federate__fed1.nr_federate__fed1 reaction 0: level: 3, is input reaction: 0, chain ID: 1, and deadline -9223372036854775808.
Federate 0: LOG: Worker 0: Invoking reaction federate__fed1.nr_federate__fed1 reaction 0 at elapsed tag (0, 0).
Federate 0: DEBUG: There are 0 outputs from reaction federate__fed1.nr_federate__fed1 reaction 0.
Federate 0: DEBUG: Worker 0: Done with reaction federate__fed1.nr_federate__fed1 reaction 0.
Federate 0: DEBUG: Worker 0 is out of ready reactions.
Federate 0: DEBUG: Scheduler: Worker 0 is the last idle thread.
Federate 0: DEBUG: Waiting with curr_reaction_level 4.
Federate 0: DEBUG: Trying to acquire the global mutex.
Federate 0: DEBUG: Waiting on MLAA with next_reaction_level 4 and MLAA 2147483647.
Federate 0: DEBUG: Exiting wait with MLAA 2147483647 and next_reaction_level 4.
Federate 0: DEBUG: DEBUG: start of rxn queue at 4 is (nil)
Federate 0: DEBUG: Scheduler: Advancing tag.
Federate 0: DEBUG: -9223372036854775808 < 1696297547042146311
Federate 0: LOG: Sending Logical Time Complete (LTC) (0, 0) to the RTI.
Federate 0: DEBUG: Sending tag (0, 0) to the RTI.
Federate 0: LOG: Earliest event on the event queue (or stop time if empty) is (2000000000, 0). Event queue has size 0.
Federate 0: DEBUG: Granted tag (7527074489812629496, 4294967295) because TAG or PTAG has been received.
Federate 0: LOG: Earliest event on the event queue (or stop time if empty) is (2000000000, 0). Event queue has size 0.
Federate 0: LOG: Waiting until elapsed time 2000000000.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297549042146311
Federate 0: DEBUG: Physical time: 1696297547067605473. Elapsed: 25459162. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Clock offset is 1696297543960277647 ns.
Federate 0: DEBUG: -------- Waiting 1974540838 ns for physical time to match logical time 2000000000.
Federate 0: DEBUG: Physical time: 1696297547067680567. Elapsed: 25534256. Offset: 1696297543960277647
Federate 0: DEBUG: -------- lf_cond_timedwait claims to have timed out, but it did not reach the target time. Waiting again.
Federate 0: DEBUG: -------- Waiting 1461345255 ns for physical time to match logical time 2000000000.
Federate 0: DEBUG: Freeing memory occupied by the federate.
Federate 0: ---- Terminating environment 0
Federate 0: LOG: --------- Start time step at tag (0, 0).
Federate 0: DEBUG: Resetting port status fields.
Federate 0: DEBUG: last_TAG=9223372036854775807
Federate 0: DEBUG: 1696297547042146311 < 9223372036854775807
Federate 0: DEBUG: Updated MLAA to 2147483647 at time 0 with last_TAG=9223372036854775807 and current time 1696297547042146311.
---- Elapsed logical time (in nsec): 0
Federate 0: DEBUG: Physical time: 1696297547581037116. Elapsed: 538890805. Offset: 1696297543960277647
---- Elapsed physical time (in nsec): 538,890,805
Federate 0: DEBUG: Physical time: 1696297547580910780. Elapsed: 538764469. Offset: 1696297543960277647
Federate 0: DEBUG: -------- lf_cond_timedwait claims to have timed out, but it did not reach the target time. Waiting again.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297549042146311
Federate 0: DEBUG: Physical time: 1696297547581172414. Elapsed: 539026103. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Clock offset is 1696297543960277647 ns.
Federate 0: DEBUG: -------- Waiting 1460973897 ns for physical time to match logical time 2000000000.
Federate 0: DEBUG: _lf_done_using: token = 0xd4d0e0, ref_count = 1.
Federate 0: DEBUG: Physical time: 1696297547581255953. Elapsed: 539109642. Offset: 1696297543960277647
Federate 0: DEBUG: -------- lf_cond_timedwait claims to have timed out, but it did not reach the target time. Waiting again.
Federate 0: DEBUG: -------- Waiting until physical time matches logical time 1696297549042146311
Federate 0: DEBUG: Physical time: 1696297547581317491. Elapsed: 539171180. Offset: 1696297543960277647
Federate 0: DEBUG: -------- Clock offset is 1696297543960277647 ns.
Federate 0: DEBUG: -------- Waiting 1460828820 ns for physical time to match logical time 2000000000.
Federate 0: DEBUG: _lf_free_token: Putting token on the recycling bin: 0xd4d0e0
Federate 0: DEBUG: Freeing token from _lf_token_recycling_bin: 0xd4d0e0
Federate 0: DEBUG: Freeing memory at 0xd4d230
Federate 0: DEBUG: Freeing allocation record at 0xd4d240
Federate 0: DEBUG: Freeing memory at 0xd4d1e0
Federate 0: DEBUG: Freeing allocation record at 0xd4d220
Federate 0: DEBUG: Freeing memory at 0xd4d290
Federate 0: DEBUG: Freeing allocation record at 0xd4d2a0
Federate 0: DEBUG: Freeing memory at 0xd4d270
Federate 0: DEBUG: Freeing allocation record at 0xd4d280
Federate 0: DEBUG: Freeing memory at 0xd4d250
Federate 0: DEBUG: Freeing allocation record at 0xd4d260
Federate 0: DEBUG: Freeing memory at 0xd4ce00
Federate 0: DEBUG: Freeing allocation record at 0xd4ce10
Federate 0: DEBUG: Physical time: 1696297547581379270. Elapsed: 539232959. Offset: 1696297543960277647
Federate 0: DEBUG: Physical time: 1696297547581379270. Elapsed: 539232959. Offset: 1696297543960277647

fed1.log

dongha1@raspberrypi:~/lingua-franca $ ./test/C/fed-gen/SimpleFederated/bin/federate__fed2
DEBUG: Physical time: 987145000. Elapsed: -9223372035867630808. Offset: 0
DEBUG: Start time: 987145000ns
---- Start execution at time Wed Dec 31 17:00:00 1969
---- plus 987145000 nanoseconds
DEBUG: _lf_new_token: Allocated memory for token: 0x1ef60e0
DEBUG: Scheduler: Initializing with 1 workers
DEBUG: Scheduler: Max reaction level: 4
DEBUG: Scheduler: Initialized vector of reactions for level 0 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 1 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 2 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 3 with size 1
DEBUG: Scheduler: Initialized vector of reactions for level 4 with size 1
Federate 1: LOG: Connecting to the RTI.
Federate 1: Successfully connected to RTI.
Federate 1: LOG: Connected to an RTI. Sending federation ID for authentication.
Federate 1: DEBUG: Waiting for response to federation ID from the RTI.
Federate 1: LOG: Received acknowledgment from the RTI.
Federate 1: Connected to RTI at 192.168.0.6:15045.
Federate 1: DEBUG: Waiting for initial clock synchronization messages from the RTI.
Federate 1: DEBUG: Physical time: 1593781246. Elapsed: 606636246. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545569753865 from RTI at local time 1593781246.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1593871117. Elapsed: 606726117. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545579969710 from RTI at local time 1593781246. (difference -1696297543986188464)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543981035606.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754398103560.
Federate 1: DEBUG: Physical time: 1651185967. Elapsed: 664040967. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545580023661 from RTI at local time 1651185967.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1651392690. Elapsed: 664247690. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545636374137 from RTI at local time 1651185967. (difference -1696297543985188170)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543956909570.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395690957.
Federate 1: DEBUG: Physical time: 1706338978. Elapsed: 719193978. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545636425958 from RTI at local time 1706338978.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1706470701. Elapsed: 719325701. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545690346682 from RTI at local time 1706338978. (difference -1696297543984007704)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543956981480.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395698148.
Federate 1: DEBUG: Physical time: 1758262811. Elapsed: 771117811. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545690407818 from RTI at local time 1758262811.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1758390479. Elapsed: 771245479. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545742172999 from RTI at local time 1758262811. (difference -1696297543983910188)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543957963763.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395796376.
Federate 1: DEBUG: Physical time: 1809035808. Elapsed: 821890808. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545742232151 from RTI at local time 1809035808.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1809167105. Elapsed: 822022105. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545798258977 from RTI at local time 1809035808. (difference -1696297543989223169)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543961144107.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754396114410.
Federate 1: DEBUG: Physical time: 1863225630. Elapsed: 876080630. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545798320066 from RTI at local time 1863225630.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1863340186. Elapsed: 876195186. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545846981004 from RTI at local time 1863225630. (difference -1696297543983755374)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543959367627.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395936762.
Federate 1: DEBUG: Physical time: 1910156281. Elapsed: 923011281. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545847034635 from RTI at local time 1910156281.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1910291189. Elapsed: 923146189. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545900746661 from RTI at local time 1910156281. (difference -1696297543990590380)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543963666913.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754396366691.
Federate 1: DEBUG: Physical time: 1974774174. Elapsed: 987629174. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545900806284 from RTI at local time 1974774174.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 1974892434. Elapsed: 987747434. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297545961404825 from RTI at local time 1974774174. (difference -1696297543986630651)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543956272250.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395627225.
Federate 1: DEBUG: Physical time: 2026052799. Elapsed: 1038907799. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297545961464585 from RTI at local time 2026052799.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 2026171096. Elapsed: 1039026096. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297546009379981 from RTI at local time 2026052799. (difference -1696297543983327182)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543959310335.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395931033.
Federate 1: DEBUG: Physical time: 2074270414. Elapsed: 1087125414. Offset: 0
Federate 1: DEBUG: Received T1 message with time payload 1696297546009458144 from RTI at local time 2074270414.
Federate 1: DEBUG: Sending T3 message to RTI.
Federate 1: DEBUG: Physical time: 2074384767. Elapsed: 1087239767. Offset: 0
Federate 1: DEBUG: Clock sync: Received T4 message with time payload 1696297546058569107 from RTI at local time 2074270414. (difference -1696297543984298693)
Federate 1: DEBUG: Clock sync: Estimated clock error: 1696297543959686035.
Federate 1: DEBUG: Clock sync: Adjusting clock offset running average by 169629754395968603.
Federate 1: LOG: Clock sync: New offset: 1696297543961233765. Round trip delay to RTI (now): 48996610. (AVG): 0. (SD): 0. Local round trip delay: 114353. Test offset: 0.
Federate 1: LOG: Finished initial clock synchronization with the RTI.
Federate 1: DEBUG: Scheduler: Initializing with 1 workers
Federate 1: DEBUG: Scheduler: Enqueueing reaction federate__fed2.ns_federate__fed1 reaction 0, which has level 0.
Federate 1: DEBUG: Scheduler: Trying to lock the mutex for level 0.
Federate 1: DEBUG: Scheduler: Locked the mutex for level 0.
Federate 1: DEBUG: Scheduler: Accessing triggered reactions at the level 0 with index 0.
Federate 1: DEBUG: Scheduler: Index for level 0 is at 0.
Federate 1: DEBUG: Scheduler: Enqueueing reaction federate__fed2.nr_federate__fed2 reaction 0, which has level 3.
Federate 1: DEBUG: Scheduler: Accessing triggered reactions at the level 3 with index 0.
Federate 1: DEBUG: Scheduler: Index for level 3 is at 0.
Federate 1: DEBUG: Resetting port status fields.
Federate 1: DEBUG: last_TAG=-9223372036854775808
Federate 1: DEBUG: Updated MLAA to 4 at time 0 with 1 items in zero-delay action table.
Federate 1: DEBUG: Synchronizing with other federates.
Federate 1: DEBUG: Physical time: 1696297546042146311. Elapsed: 1696297545055001311. Offset: 1696297543961233765
Federate 1: DEBUG: Sending time 1696297546042146311 to the RTI.
Federate 1: DEBUG: Read 9 bytes.
Federate 1: Starting timestamp is: 1696297547042146311.
Federate 1: DEBUG: Physical time: 1696297546045151895. Elapsed: 1696297545058006895. Offset: 1696297543961233765
Federate 1: LOG: Current physical time is: 1696297546045151895.
Federate 1: DEBUG: 1696297547042146311 < 1696297549042146311
Federate 1: LOG: Waiting for start time 1696297547042146311 plus STA 0.
Federate 1: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 1: DEBUG: Physical time: 1696297546045405896. Elapsed: -996740415. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Clock offset is 1696297543961233765 ns.
Federate 1: DEBUG: -------- Waiting 996740415 ns for physical time to match logical time 0.
Federate 1: DEBUG: -------- wait_until interrupted before timeout.
Federate 1: DEBUG: Physical time: 1696297546045459118. Elapsed: -996687193. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Returned from wait, having waited 53222 ns.
Federate 1: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 1: DEBUG: Physical time: 1696297546045497581. Elapsed: -996648730. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Clock offset is 1696297543961233765 ns.
Federate 1: DEBUG: -------- Waiting 996648730 ns for physical time to match logical time 0.
Federate 1: DEBUG: -------- wait_until interrupted before timeout.
Federate 1: DEBUG: Physical time: 1696297546045547767. Elapsed: -996598544. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Returned from wait, having waited 50186 ns.
Federate 1: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 1: DEBUG: Physical time: 1696297546045585396. Elapsed: -996560915. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Clock offset is 1696297543961233765 ns.
Federate 1: DEBUG: -------- Waiting 996560915 ns for physical time to match logical time 0.

...

Federate 1: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 1: DEBUG: Physical time: 1696297546803720933. Elapsed: -238425378. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Clock offset is 1696297543961233765 ns.
Federate 1: DEBUG: -------- Waiting 238425378 ns for physical time to match logical time 0.
Federate 1: DEBUG: -------- wait_until interrupted before timeout.
Federate 1: DEBUG: Physical time: 1696297546803769137. Elapsed: -238377174. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Returned from wait, having waited 48204 ns.
Federate 1: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 1: DEBUG: Physical time: 1696297546803805841. Elapsed: -238340470. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Clock offset is 1696297543961233765 ns.
Federate 1: DEBUG: -------- Waiting 238340470 ns for physical time to match logical time 0.
Federate 1: DEBUG: -------- wait_until interrupted before timeout.
Federate 1: DEBUG: Physical time: 1696297546803852934. Elapsed: -238293377. Offset: 1696297543961233765
Federate 1: DEBUG: -------- Returned from wait, having waited 47093 ns.
Federate 1: DEBUG: --^CFederate 1: DEBUG: -------- Waiting until physical time matches logical time 1696297547042146311
Federate 1: LOG: Resigned.
Federate 1: DEBUG: Requesting closing of incoming P2P sockets.
Federate 1: DEBUG: Waiting for inbound p2p socket listener threads.
Federate 1: DEBUG: Waiting for RTI's socket listener threads.

@erlingrj
Copy link
Collaborator

erlingrj commented Oct 4, 2023

A quick observation from me is that the system clock on the RPis are terribly out of sync. They start in 1969. In theory, our distributed infrastructure should be able to handle this, but I wouldnt be surprised if there are some edge-cases arising when we try to adjust the clocks by 50 years. This definitely deserves debugging, but an easy workaround for you would be disabling clock-sync and use NTP or PTP instead. If the RPis have internet access they can just run a simple NTP client. If they dont have internet access you could look into running linuxPTP and phc2sys on your Ubuntu and the RPis. This would rely on software timestamping but should work fine.

@erlingrj erlingrj mentioned this issue Oct 7, 2023
Merged
@erlingrj
Copy link
Collaborator

erlingrj commented Oct 7, 2023

@Jakio815 Can you try out this bug-fix: lf-lang/reactor-c#288

@Jakio815
Copy link
Collaborator Author

Jakio815 commented Oct 9, 2023

@Jakio815 Can you try out this bug-fix: lf-lang/reactor-c#288

I'll take a look, but not sure what's really the problem. Is it even related with #2048 ?

@erlingrj
Copy link
Collaborator

erlingrj commented Oct 9, 2023

What I mean is that I believe this PR will fix your issue. I also experienced wierd behaviors on RPi and found this overflow bug

@erlingrj
Copy link
Collaborator

The fix is merged into the main branch of reactor-c. I will close this issue as I am quite sure that your issue is fixed.

# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees
No one assigned
Labels
bug Something isn't working federated
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@edwardalee @erlingrj @Jakio815