bugCERTI - Bugs: bug #57773, Possible deadlock in RTIA,...

 
 

bug #57773: Possible deadlock in RTIA, possibly related to <NM_Synchronization_Point_Achieved>

Submitter:  janette cardoso <cardoso>
Submitted:  Sat 08 Feb 2020 09:05:48 PM UTC
   
 
Category:  JavaCERTI Severity:  * 3 - Normal
Item Group:  Software error Status:  Need Info
Privacy:  Public Assigned to:  jb_ch
Open/Closed:  Open Release:  * GIT-master
Reproducibility:  None Fixed Release:  * GIT-master
* Mandatory Fields

Add a New Comment Rich Markup
   

Mon 17 Feb 2020 02:31:54 AM UTC, comment #3: 

Hello,

According to what I have heard from j.cardoso two months ago, this issue might have been fixed per her recent work with jcerti. But unfortunately it looks that this is the same as #55592 (duplicate therefore and same issue still here).

As already discussed with j.cardoso, we have never ever observed such behavior launching multiples scripts and very big federations (up to 400 federates, all C/C++ code and all using one pr many synchronixation points).

Therefore, I don't think this issue comes from the certi but most likely from some inconsistencies between Java virtual machine code (federate) and Rtia executable (C++) and how all these components are working toguether in your script/test environment. The issue might also comes from the jcerti itself.

Are you able to provide a simple example to reproduce the behavior? (I mean without your entire script chain). If yes, i will have a look at it in June.

Best regards,
Jb Ch






JbCh <jb_ch>
Group administrator
Tue 11 Feb 2020 03:26:14 PM UTC, comment #2: 

To be clearer, based on the logs from the RTI, below is the sequence of events that leads to the error.
This happens nondeterministically in one out of every 64 or so runs, so it is probably a concurrency bug in the RTIG.
It looks like the list of sockets connected to RTIAs is getting corrupted.
I was unable to find any explicit threading nor any mutexes in the RTIG source code at all,
so I really have no idea how this could be coming about.

The test case has two federates.  The steps that are probably erroneous are marked with *:

1. RTIG accepts a new client and sets up a socket connection (socket ID 7).
2. RTIG receives NM_Create_Federation_Execution
3. RTIG sends back NM_Create_Federation_Execution to socket 7
4. RTIG receives NM_Join_Federation_Execution on socket 7
5. RTIG says: Send back NM_Additional_Fom_Module to 0 federates    ?? This message goes nowhere. Because there are no other federates yet?
6. RTIG sends back NM_Join_Federation_Execution to socket 7
7. RTIG receives NM_Subscribe_Object_Class on socket 7
8. RTIG says: Send back NM_Start_Registration_For_Object_Class to 0 federates  ?? Again, a message to nowhere.
*9. RTIG tries to send back NM_Subscribe_Object_Class to 1 federate, but it has lost the socket pointer so sends it to nullptr. Exact log message:

HLALOG - 1581078446.157621  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:446 > Send back NM_Subscribe_Object_Class to 1 federates
HLALOG - 1581078446.157707  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:452 > to nullptr

10. RTIG accepts new client and sets up a new socket (socket ID 8).
11. RTIG receives NM_Create_Federation_Execution on socket 8.
12. RTIG catches exception FederationExecutionAlreadyExists and either sends exception back or NM_Create_Federation_Execution (log is unclear)
13. RTIG receives NM_Join_Federation_Execution on socket 8.
*14. RTIG says: "Send back NM_Additional_Fom_Module to 1 federates" but sends this to nullptr again (should be socket 7).
15. RTIG sends back NM_Join_Federation_Execution to socket 8.
16. RTIG receives NM_Publish_Object_Class on socket 8.
17. RTIG sends back NM_Start_Registration_For_Object_Class to socket 8.
18. RTIG sends back NM_Publish_Object_Class to socket 8.
19. RTIG receives NM_Register_Object on socket 8.
20. RTIG tries to send back NM_Discover_Object to 1 federate, but sends to nullptr again.
21. RTIG sends back NM_Register_Object to socket 8.
22. RTIG receives NM_Set_Time_Constrained on socket 8.
23. RTIG sends back NM_Time_Constrained_Enabled to socket 8.
24. RTIG receives NM_Set_Time_Regulating on socket 8.
*25. RTIG sends back NM_Set_Time_Regulating and NM_Time_Regulation_Enabled to 2 federates, socket 8 and nullptr.
26. RTIG receives NM_Enable_Asynchronous_Delivery on socket 8 and has 0 responses
27. RTIG receives NM_Register_Federation_Synchronization_Point on socket 8.
*28. RTIG sends back NM_Announce_Synchronization_Point to 2 federates, socket 8 and nullptr.
29. RTIG sends back NM_Confirm_Synchronization_Point_Registration to socket 8.
30. RTIG receives NM_Synchronization_Point_Achieved on socket 8 and has no responses.

At this point, the federation hangs forever.
After about 15 minutes, our test script kills the process.

The federation is hanging because the RTIG lost track of the first federate.
Yet it still thinks there are two federates needing to synchronize on the synchronization point.
It only ever receives one NM_Synchronization_Point_Achieved (from the second federate to join).
The first federate is itself hung waiting for the response at line 9.
We modified the JCERTI code to have a timeout on a socket read to prevent the hang, but the federate can't proceed anyway.

Edward A. Lee <eal>
Group Member
Mon 10 Feb 2020 09:22:06 AM UTC, comment #1: 

The bug seems to be related to the RTIG failing to announce a synchronization point to all federates.  See the debug output below from the RTIG.  The first line marked with "*****" shows that the RTIG failed to send the announcement to the second federate. The second line marked with "******" shows a 15 minute time jump until the test timed out and a new test was started.  All other tests that pass successfully send the announcement to all federates.  Why would the RTIG lose track of its federates so it can't broadcast the announcement to them?

Remark: When we first discovered the JCERTI was blocking forever on a read from a socket, we added a timeout to JCERTI's RTIAmbassasor's socket reads, which may account for the network read error reported by Janette below.  The root problem, however, seems to be in RTIG failing to announce the synchronization point to all federates.

HLALOG - 1581078447.168407  - NetworkMessage::63 > Deserialize <NM_Register_Federation_Synchronization_Point>
HLALOG - 1581078447.168517  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/MessageProcessor.cc:511 > Federation 19: registerFedSyncPoint from federate 2
HLALOG - 1581078447.168642  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/MessageProcessor.cc:539 > Federation 19 is now synchronizing
HLALOG - 1581078447.168745  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:444 > 2 responses
HLALOG - 1581078447.168867  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:446 > Send back NM_Announce_Synchronization_Point to 2 federates
HLALOG - 1581078447.169015  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:449 > to 8
HLALOG - 1581078447.169121  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:452 > to nullptr   ****************************** suspicious.
HLALOG - 1581078447.169185  - NetworkMessage::42 > Serialize <NM_Announce_Synchronization_Point>
HLALOG - 1581078447.169300  - NetworkMessage::116 > Sending <NM_Announce_Synchronization_Point> whose buffer has <55> bytes
HLALOG - 1581078447.169407  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:446 > Send back NM_Confirm_Synchronization_Point_Registration to 1 federates
HLALOG - 1581078447.169521  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:449 > to 8
HLALOG - 1581078447.169660  - NetworkMessage::42 > Serialize <NM_Confirm_Synchronization_Point_Registration>
HLALOG - 1581078447.169718  - NetworkMessage::116 > Sending <NM_Confirm_Synchronization_Point_Registration> whose buffer has <41> bytes
HLALOG - 1581078447.172744  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:203 > Incoming message on socket 8
HLALOG - 1581078447.172860  - NetworkMessage::143 > Got a MsgBuf of size 39 bytes (including  reserved)
HLALOG - 1581078447.172951  - NetworkMessage::63 > Deserialize <NetworkMessage (generic)>
HLALOG - 1581078447.173034  - NetworkMessage::63 > Deserialize <NM_Synchronization_Point_Achieved>
HLALOG - 1581078447.173252  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/MessageProcessor.cc:566 > Federation 19: synchronizationPointAchieved from federate 2
HLALOG - 1581078447.173353  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/MessageProcessor.cc:575 > Federate 2 has synchronized
HLALOG - 1581078447.173498  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:444 > 0 responses
    ***************************************************************** 15 minute time jump.
HLALOG - 1581079346.179170  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:228 > New client
HLALOG - 1581079346.179333  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:513 > Accepting new connection
HLALOG - 1581079346.343667  - /Users/eal/pthla/hla1516e/certi4-0.0/RTIG/RTIG.cc:203 > Incoming message on socket 9

Edward A. Lee <eal>
Group Member
Sat 08 Feb 2020 09:05:48 PM UTC, original submission:  

We would like to know where to put a trace in the code of CERTI (or may be JCERTI) for try to solve this problem. It was already posted on ticket #55592, one year ago.
We are using now:
- CERTI, branch dev-scalian/alaine-compatibility-mac
But the error occurs also with the master
- JCERTI, branch br_ptII_berkeley that differs from the master only on createFederationExecution (sends a strig).
- these federates are mostly compliant with HLA 1.3.

The RTIG get stuck after "Deserialize <NM_Synchronization_Point_Achieved>"

Here some details:


We use a batch with 19 tests. Each test is a federation with 1 or 2 federates.
When there are 2 federates, the last one registers the synchronization point.
The rtig is launched by hand. A first batch was launched, and all 19 passed.
Then a second batch was launched at 16:39:31.487 that has failed.
Sometimes we can run 10 batches before the first failure occurs...

When the 4th test (federation) of this 2nd batch starts running at 16:40:25,
the federate "constTT"  creates the federation and joins it. Then the exception
"libRTI: Network Read Error" is thrown  when trying to initialize the RTI Ambassador:
CertiRtiAmbassador.java:3842 is related to disableAttributeScopeAdvisorySwitch() method.

Then prodTT (that register the synchronization point) of same federation successfully
creates its RTI ambassador, joins the federation, initialize its RTIA.
At that moment, the first federate, constTT unsubscribe, try to resign the federation,
when an exception occurs.

At that point, there are 2 rtia processes blocked.

On the terminal T2 where the rtig was running (with RTIG_MSG=D, RTIA_MSG=D, RTIA=D)
at time 1581176431.449663 = Feb 8, 16:40:31.449, it is blocked at this line:

HLALOG - 1581176431.449663  - NetworkMessage::63 > Deserialize <NM_Synchronization_Point_Achieved>

In terminal T1 we can also see:
Caused by: hla.rti.RTIinternalError: libRTI: Network Read Error serial:0
at certi.rti.impl.CertiRtiAmbassador.processRequest(CertiRtiAmbassador.java:3842)
at certi.rti.impl.CertiRtiAmbassador.subscribeObjectClassAttributes(CertiRtiAmbassador.java:967)

It stays blocked until the next test (of the batch) is automatically launched at 16:55:25.
These 15 min are due to the timeout of the test.

A new error occurs again at 16:56:14.255, with a similar scenario.

On terminal T1 where the tests were launched we can see:
- first federate ReceiverTAR22 tries to initialize the RTIA
- second federate SenderTAR22 joins the federation and successfully initialize its RTIA
- ReceiverTAR22 wrapups (Unsubscribing, resigning, RTI exception, try to destroy the federation)

On terminal T2 where the rtig is running, it's blocked at:
HLALOG - 1581177374.255544  - NetworkMessage::63 > Deserialize <NetworkMessage (generic)>
HLALOG - 1581177374.255562  - NetworkMessage::63 > Deserialize <NM_Synchronization_Point_Achieved>

The result of the test batch is that 2 tests had failures.

janette cardoso <cardoso>
Group Member

 

(Note: upload size limit is set to 16384 kB, after insertion of the required escape characters.)

Attach Files:
   
   
Comment:
   

No files currently attached

 

Depends on the following items: None found

Items that depend on this one: None found

 

Carbon-Copy List
  • -email is unavailable- added by jb_ch (Posted a comment)
  • -email is unavailable- added by eal (Posted a comment)
  • -email is unavailable- added by cardoso (Submitted the item)
  • -email is unavailable- added by cardoso
  •  

    Follow 3 latest changes.

    Date Changed by Updated Field Previous Value => Replaced by
    2020-02-17 jb_ch StatusNone Need Info
        Assigned toNone jb_ch
    2020-02-08 cardoso Carbon-Copy- Added eal

    Back to the top

    Powered by Savane 3.13-4448.
    Corresponding source code