The Enterprise Manager Table IS_USR_GP_USER is Empty

Description

After a scheduled data loader job runs, the related tables in the Enterprise Manager warehouse appear empty.
In particular, the related tables IS_USR_GP_USER and IS_USR_GP_USR_GP are empty after scheduled jobs run. However, lookup tables, like EM_USR_GP and EM_USER, contain data. 
It was also found that the related table IS_USR_GP_USER could contain data after a manual data load; however, manually executing the data load would populate the table and then be erased after the next batch. 

Error Messages

Although errors did not appear during this process, unfamiliar messages did appear in the log file MigrationSQL. As you can see, on 08-29, data was populated to the IS_USR_GP_USER table. However, at 08-30, data was not populated into the IS_USR_GP_USER table, but into the table IS_REP_ATT.
2019-08-29 13:55:28.242 [HOST:CSSDUB5SV26][SERVER:][PID:30228][THR:17660][ETL][Migration SQL] SQL Executed: SELECT DISTINCT * FROM STG_IS_USR_GP_USER ORDER BY EM_USER_GUID
2019-08-29 13:55:28.632 [HOST:CSSDUB5SV26][SERVER:][PID:30228][THR:17660][ETL][Migration SQL] SQL Executed: INSERT INTO IS_USR_GP_USER ( EM_USR_GP_ID, EM_USER_ID,  IS_REPOSITORY_ID) select   L0.EM_USR_GP_ID,  L1.EM_USER_ID,  M0.REP_ID FROM  EM_USR_GP L0, EM_USER L1,  STG_IS_USR_GP_USER R0, EM_MD M0 WHERE R0.EM_USR_GP_GUID =  L0.EM_USR_GP_GUID AND  L0.IS_REPOSITORY_ID = M0.REP_ID AND R0.EM_USER_GUID =  L1.EM_USER_GUID AND  L1.IS_REPOSITORY_ID = M0.REP_ID AND  R0.IS_REPOSITORY_GUID = M0.REP_GUID AND NOT EXISTS (SELECT 1 FROM  IS_USR_GP_USER W0 WHERE W0.EM_USR_GP_ID =  L0.EM_USR_GP_ID AND W0.EM_USER_ID =  L1.EM_USER_ID AND  W0.IS_REPOSITORY_ID = M0.REP_ID) 
2019-08-30 07:38:29.176 [HOST:CSSDUB5SV26][SERVER:][PID:30032][THR:28696][ETL][Migration SQL] SQL Executed: SELECT DISTINCT * FROM STG_IS_REP_ATT ORDER BY IS_REP_GUID
2019-08-30 07:38:39.893 [HOST:CSSDUB5SV26][SERVER:][PID:30032][THR:28696][ETL][Migration SQL] SQL Executed: INSERT INTO IS_REP_ATT ( IS_REP_ID, IS_ATT_ID,  IS_PROJ_ID) select   L1.IS_REP_ID,  L2.IS_ATT_ID,  P0.IS_PROJ_ID FROM  IS_REP L1, IS_ATT L2,  STG_IS_REP_ATT R0, EM_MD M0, IS_PROJ P0 WHERE R0.IS_REP_GUID =  L1.IS_REP_GUID AND  L1.IS_PROJ_ID = P0.IS_PROJ_ID AND R0.IS_ATT_GUID =  L2.IS_ATT_GUID AND  L2.IS_PROJ_ID = P0.IS_PROJ_ID AND  R0.IS_REPOSITORY_GUID = M0.REP_GUID AND R0.IS_PROJ_GUID = P0.IS_PROJ_GUID AND P0.IS_REPOSITORY_ID = M0.REP_ID AND NOT EXISTS (SELECT 1 FROM  IS_REP_ATT W0 WHERE W0.IS_REP_ID =  L1.IS_REP_ID AND W0.IS_ATT_ID =  L2.IS_ATT_ID AND  W0.IS_PROJ_ID = P0.IS_PROJ_ID)
 

Why's this happening?

Typical Workflow

On a normal basis, before the data load, the table STG_IS_USR_GP_USER is empty and the table IS_USR_GP_USER contains data. During the DSS Migration, the data is populated to the table STG_IS_USR_GP_USER. Then, during the ETL, the data from the table IS_USR_GP_USER is emptied and the data from STG_IS_USR_GP_USER is placed in the IS_USR_GP_USER table. 
In the end, the data is emptied from the STG_IS_USR_GP_USER table. So the final results should be the STG_IS_USR_GP_USER table is empty and the IS_USR_GP_USER table contains data.
However, this is not the case in this situation.
 

Log Analysis

The following log files were identified in MAEntMgr.xml:
<log4j:event logger="MAEntMgr" timestamp="1567084391616" level="INFO" thread="pool-2-thread-1">
<log4j:message type ="DEFAULT"><![CDATA[Cleaning up recovery data]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567084391616" level="DEBUG" thread="pool-2-thread-1">
<log4j:message type ="DEFAULT"><![CDATA[End reached!]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567084391725" level="INFO" thread="pool-2-thread-1">
<log4j:message type ="DEFAULT"><![CDATA[Dataload ended: Daily at 12 45 AM]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567084393363" level="DEBUG" thread="pool-2-thread-1">
<log4j:message type ="DEFAULT"><![CDATA[Finished executing: Warehouse and Fact Update]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567145700119" level="INFO" thread="Timer-43">
<log4j:message type ="DEFAULT"><![CDATA[Dataload added to the queue Daily at 6 15 AM]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567145700135" level="INFO" thread="Timer-43">
<log4j:message type ="DEFAULT"><![CDATA[Dataload queue: {1A377E2916C474587CC6901911945551=Daily at 6 15 AM}]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567145700696" level="INFO" thread="Timer-43">
<log4j:message type ="DEFAULT"><![CDATA[Clean up the recovery data for last failed data load]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567145725173" level="INFO" thread="Timer-43">
<log4j:message type ="DEFAULT"><![CDATA[Executing C:\Program Files (x86)\MicroStrategy\Enterprise Manager\Scripts\clean_recovery_data.sql on tmi_statistics]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567145728168" level="INFO" thread="Timer-43">
<log4j:message type ="DEFAULT"><![CDATA[Finished executing C:\Program Files (x86)\MicroStrategy\Enterprise Manager\Scripts\clean_recovery_data.sql on tmi_statistics]]></log4j:message>
<log4j:event logger="MAEntMgr" timestamp="1567145728184" level="INFO" thread="Timer-43">
<log4j:message type ="DEFAULT"><![CDATA[Finished executing Claen up the recovery data]]></log4j:message>
From the file, you can see that the last data load has finished successfully and all the data was cleaned from the EM_RECOVERY table based on the "Cleaning up recovery data" operation. But, once the new data load begins, the EM Service found there was data in the table EM_RECOVERY and triggered the "Clean up the recovery data for last failed data load" operation.
Then you can also see that the data load start time is set to 1567145700119, which is 2019-8-30 07:15:00. But, in the EM Migration Trace Log, it says: 
2019-08-30 07:14:31.243 [HOST:CSSDUB5SV26][SERVER:CastorServer][PID:1696][THR:4404][Kernel][EM Migration Trace] Enter 'EMMigrationImpl(2, 8/29/2019, 8/30/2019)' near ..\..\SourceCode\MsiMigration\EMMigration.cpp(482)
2019-08-30 07:14:31.243 [HOST:CSSDUB5SV26][SERVER:CastorServer][PID:1696][THR:4404][Kernel][EM Migration Trace] RespositoryID is E4B9E9CC4383C0E1772B68A182C5A609
2019-08-30 07:14:31.275 [HOST:CSSDUB5SV26][SERVER:CastorServer][PID:1696][THR:4404][Kernel][EM Migration Trace] First dataload flag is false and Journaling setting is false 
Which indicates that the data load happened on 2019-08-30 07:14:31.243.
This indicates that there may be more than one data load running at this time. This idea was further confirmed after analyzing the MSTR_Stats log that illustrated two INSERT operations on the STG_IS_USR_GP_USER table.
 

Ultimate Reason this Occurs?

It appears you may have two or more Enterprise Manager Services on your machines with the same Enterprise Manager warehouse. This is why when you manually perform a data load, tables are populated with data. The manual data load is only executed on one machine, but the scheduled data load is triggered on all the machines.
 

Solution

To resolve this problem, run the following SQL statement on the Enterprise Manager warehouse:

SELECT  DAY_ID AS “Date”, 

                CLIENTMACHINE AS “Data Loader service machine”   FROM  IS_SESSION_STATSWHERE  EVENTSOURCE = 14GROUP BY  DAY_ID, CLIENTMACHINEORDER BY  DAY_ID desc;  

We could see this result:

2019-09-05 Server Machine: Client Machine: 172.20.236.164

2019-09-05 Server Machine: Client Machine: 172.20.236.165

2019-09-04 Server Machine: Client Machine: 172.20.236.164

2019-09-04 Server Machine: Client Machine: 172.20.236.165

This SQL will indicate if there are more than two services running on the same Enterprise Manager warehouse. If you do have more than one service running, stop the Enterprise Manager Service on all but one node.
Note: It's recommended to set the Start time from Automatic to Manual to prevent it from automatically running at the next time you restart the machine.