Task #9607: added logging in MACScheduler::_updatePlannedList() to identify if...

Task #9607: added logging in MACScheduler::_updatePlannedList() to identify if the missed observations are due to a potential race-condiction in itsOTDBconnection->getTreeGroup and the timeBeforeStart check

MAC/APL/MainCU/src/MACScheduler/MACScheduler.cc

@@ -624,15 +624,17 @@ void MACScheduler::_doOTDBcheck()
 //
 void MACScheduler::_updatePlannedList()
 {
-	LOG_DEBUG("_updatePlannedList()");
+	LOG_INFO("_updatePlannedList()");
 
 	// get time info
 	time_t	now = time(0);
 	ptime	currentTime = from_time_t(now);
 	ASSERTSTR (currentTime != not_a_date_time, "Can't determine systemtime, bailing out");
 
+        LOG_INFO_STR("calling getTreeGroup");
 	// get new list (list is ordered on starttime) of planned observations
 	vector<OTDBtree> plannedDBlist = itsOTDBconnection->getTreeGroup(1, itsPlannedPeriod, itsExclPLcluster);
+        LOG_INFO_STR("called getTreeGroup, nr of items in plannedDBlist: " << plannedDBlist.size());
 
 	if (!plannedDBlist.empty()) {
 		LOG_DEBUG(formatString("OTDBCheck:First planned observation (%d) is at %s (active over %d seconds)",
@@ -697,7 +699,11 @@ void MACScheduler::_updatePlannedList()
 
 		// should this observation (have) be(en) started?
 		int		timeBeforeStart = time_duration(plannedDBlist[idx].starttime - currentTime).total_seconds();
-//		LOG_DEBUG_STR(obsName << " starts over " << timeBeforeStart << " seconds");
+                LOG_INFO(formatString("%s starts at %s which is in %d seconds",
+                                obsName.c_str(),
+                                to_simple_string(plannedDBlist[idx].starttime).c_str(),
+                                timeBeforeStart));
+
 		if (timeBeforeStart > 0 && timeBeforeStart <= (int)itsQueuePeriod) {
 			if (itsPreparedObs[obsID].prepReady == false) {
 				LOG_INFO_STR("Observation " << obsID << " must be started but is not claimed yet.");
@@ -718,14 +724,14 @@ void MACScheduler::_updatePlannedList()
 
 					// add controller to our 'monitor' administration
 					itsControllerMap[cntlrName] =  obsID;
-					LOG_DEBUG_STR("itsControllerMap[" << cntlrName << "]=" <<  obsID);
+					LOG_INFO_STR("itsControllerMap[" << cntlrName << "]=" <<  obsID);
 					if (!itsPreparedObs[obsID].parsetDistributed) {
 						_setParsetOnMsgBus(observationParset(obsID));
 						itsPreparedObs[obsID].parsetDistributed = true;
 					}
 				}
 				else {
-					LOG_DEBUG_STR("Observation " << obsID << " is already (being) started");
+					LOG_INFO_STR("Observation " << obsID << " is already (being) started");
 				}
 			}
 		}