Merge pull request #2585 from AllenInstitute/bugfix/2585-better-error-reporting

Improve error reporting and localisation options for lingering RTEs

Author: MichaelHuth

Packages/MIES/MIES_AnalysisFunctionManagement.ipf

@@ -14,7 +14,7 @@
 /// @return Valid analysis function return types, zero otherwise, see also @ref AnalysisFunctionReturnTypes
 Function AFM_CallAnalysisFunctions(string device, variable eventType)
 
-	variable i, valid_f1, valid_f2, valid_f3, ret, DAC, sweepsInSet, hwIsSutter
+	variable i, valid_f1, valid_f2, valid_f3, ret, DAC, sweepsInSet, hwIsSutter, err
 	variable realDataLengthAD, realDataLengthDA, sweepNo, fifoPositionAD, fifoPositionDA, sampleIntDA, sampleIntAD
 	string func, msg
 	STRUCT AnalysisFunction_V3 s
@@ -170,8 +170,12 @@ Function AFM_CallAnalysisFunctions(string device, variable eventType)
 			endif
 		catch
 			msg = GetRTErrMessage()
-			ClearRTError()
-			printf "The analysis function %s aborted with error \"%s\", this is dangerous and must *not* happen!\r", func, msg
+			err = ClearRTError()
+			if(err)
+				printf "The analysis function %s aborted due to a runtime error (%d) \"%s\".\r", func, err, msg
+			else
+				printf "The analysis function %s aborted with V_AbortCode (%d).\r", func, V_AbortCode
+			endif
 
 			NVAR errorCounter = $GetAnalysisFuncErrorCounter(device)
 			errorCounter += 1

Packages/MIES/MIES_ExperimentDocumentation.ipf

@@ -192,8 +192,10 @@ static Function ED_createTextNotes(WAVE/T incomingTextualValues, WAVE/T incoming
 
 	numCols                = DimSize(incomingTextualValues, COLS)
 	lastValidIncomingLayer = (DimSize(incomingTextualValues, LAYERS) == 0) ? 0 : (DimSize(incomingTextualValues, LAYERS) - 1)
+
+	AssertOnAndClearRTError()
 	for(i = 0; i < numCols; i += 1)
-		values[rowIndex][indizes[i]][0, lastValidIncomingLayer] = NormalizeToEOL(incomingTextualValues[0][i][r], "\n")
+		values[rowIndex][indizes[i]][0, lastValidIncomingLayer] = NormalizeToEOL(incomingTextualValues[0][i][r], "\n"); AbortOnRTE
 	endfor
 
 	SetNumberInWaveNote(values, NOTE_INDEX, rowIndex + 1)
@@ -295,8 +297,10 @@ static Function ED_createWaveNotes(WAVE incomingNumericalValues, WAVE/T incoming
 
 	numCols                = DimSize(incomingNumericalValues, COLS)
 	lastValidIncomingLayer = (DimSize(incomingNumericalValues, LAYERS) == 0) ? 0 : (DimSize(incomingNumericalValues, LAYERS) - 1)
+
+	AssertOnAndClearRTError()
 	for(i = 0; i < numCols; i += 1)
-		values[rowIndex][indizes[i]][0, lastValidIncomingLayer] = incomingNumericalValues[0][i][r]
+		values[rowIndex][indizes[i]][0, lastValidIncomingLayer] = incomingNumericalValues[0][i][r]; AbortOnRTE
 	endfor
 
 	SetNumberInWaveNote(values, NOTE_INDEX, rowIndex + 1)

Packages/MIES/MIES_MiesUtilities_Logbook.ipf

@@ -625,8 +625,8 @@ threadsafe Function/WAVE GetLastSetting(WAVE values, variable sweepNo, string se
 		first = rowCache[sweepNo][%first][entrySourceTypeIndex]
 		last  = rowCache[sweepNo][%last][entrySourceTypeIndex]
 
-		WAVE/Z settings = GetLastSettingNoCache(values, sweepNo, setting, entrySourceType,     \
-		                                        first = first, last = last, rowIndex = rowIndex)
+		WAVE/Z settings = GetLastSettingNoCache(values, sweepNo, setting, entrySourceType,                              \
+		                                        first = first, last = last, rowIndex = rowIndex, settingCol = settingCol)
 
 		if(WaveExists(settings))
 			ASSERT_TS(first >= 0 && last >= 0 && rowIndex >= 0, "invalid return combination from GetLastSettingNoCache")
@@ -749,8 +749,10 @@ threadsafe Function/WAVE GetLastSettingNoCache(WAVE values, variable sweepNo, st
 				endif
 			endif
 
-			statusText[] = textualValues[i][settingCol][p]
-			lengths[]    = strlen(statusTexT[p])
+			AssertOnAndClearRTError()
+			statusText[] = textualValues[i][settingCol][p]; AbortOnRTE
+
+			lengths[] = strlen(statusTexT[p])
 
 			// return if we have at least one non-empty entry
 			if(Sum(lengths) > 0)
@@ -848,7 +850,8 @@ threadsafe Function/WAVE GetLastSettingNoCache(WAVE values, variable sweepNo, st
 				endif
 			endif
 
-			status[] = numericalValues[i][settingCol][p]
+			AssertOnAndClearRTError()
+			status[] = numericalValues[i][settingCol][p]; AbortOnRTE
 
 			if(HasOneValidEntry(status))
 				if(!ParamIsDefault(rowIndex))
@@ -1984,3 +1987,40 @@ Function/S StringifyLogbookMode(variable mode)
 			break
 	endswitch
 End
+
+/// @brief Invalidates the row and index caches for all labnotebook and results wave
+Function InvalidateLBIndexAndRowCaches()
+
+	string device
+
+	DFREF dfr = GetCacheFolder()
+
+	if(IsDataFolderEmpty(dfr))
+		return NaN
+	endif
+
+	WAVE/T devices = ListToTextWave(GetAllDevices(), ";")
+
+	// labnotebook (numerical and textual) of all devices
+	for(device : devices)
+		Make/FREE/WAVE valuesWave = {GetLBNumericalValues(device), GetLBTextualValues(device)}
+
+		InvalidateLBIndexAndRowCaches_Impl(valuesWave)
+	endfor
+
+	Make/FREE/WAVE valuesWave = {GetNumericalResultsValues(), GetTextualResultsValues()}
+	InvalidateLBIndexAndRowCaches_Impl(valuesWave)
+End
+
+static Function InvalidateLBIndexAndRowCaches_Impl(WAVE valuesWave)
+
+	string key
+
+	for(WAVE values : valuesWave)
+		Make/FREE/T keys = {CA_CreateLBIndexCacheKey(values), CA_CreateLBRowCacheKey(values)}
+
+		for(key : keys)
+			CA_DeleteCacheEntry(key)
+		endfor
+	endfor
+End

Packages/MIES/MIES_MiesUtilities_System.ipf

@@ -213,6 +213,8 @@ Function BackupCacheWaves()
 	variable i, numEntries
 	string names = ""
 
+	InvalidateLBIndexAndRowCaches()
+
 	DFREF dfr = GetCacheFolder()
 
 	WAVE/WAVE cacheWaves = ListToWaveRefWave(GetListOfObjects(dfr, ".*", fullPath = 1))

Packages/MIES/MIES_Utilities_ProgramFlow.ipf

@@ -148,6 +148,10 @@ Function ASSERT(variable var, string errorMsg, [variable extendedOutput])
 	try
 		AbortOnValue var == 0, 1
 	catch
+#ifndef AUTOMATED_TESTING
+		AssertOnAndClearRTError()
+#endif // !AUTOMATED_TESTING
+
 		if(ParamIsDefault(extendedOutput))
 			extendedOutput = 1
 		else
@@ -201,6 +205,7 @@ Function ASSERT(variable var, string errorMsg, [variable extendedOutput])
 			Make/FREE/T tpStates = {NONE}
 			Make/FREE/T daqStates = {NONE}
 			Make/FREE/T acqStates = {NONE}
+			Make/FREE/T fifoPos = {NONE}
 
 			if(!SVAR_Exists(lockedDevices) || IsEmpty(lockedDevices))
 				lockedDevicesStr = NONE
@@ -209,7 +214,7 @@ Function ASSERT(variable var, string errorMsg, [variable extendedOutput])
 
 				numLockedDevices = ItemsInList(lockedDevicesStr)
 
-				Redimension/N=(numLockedDevices) sweeps, daqStates, tpStates, acqStates
+				Redimension/N=(numLockedDevices) sweeps, daqStates, tpStates, acqStates, fifoPos
 
 				for(i = 0; i < numLockedDevices; i += 1)
 					device = StringFromList(i, lockedDevicesStr)
@@ -220,6 +225,7 @@ Function ASSERT(variable var, string errorMsg, [variable extendedOutput])
 					tpStates[i]  = TestPulseRunModeToString(testpulseMode)
 					daqStates[i] = DAQRunModeToString(runMode)
 					acqStates[i] = AS_StateToString(ROVar(GetAcquisitionState(device)))
+					fifoPos[i]   = num2istr(ROVar(GetFifoPosition(device)))
 				endfor
 			endif
 
@@ -232,12 +238,13 @@ Function ASSERT(variable var, string errorMsg, [variable extendedOutput])
 			print stacktrace
 
 			print "~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~"
-			printf "Time: %s\r", GetIso8601TimeStamp(localTimeZone = 1)
+			printf "Time: %s\r", GetIso8601TimeStamp(localTimeZone = 1, numFracSecondsDigits = 3)
 			printf "Locked device: [%s]\r", RemoveEnding(lockedDevicesStr, ";")
 			printf "Current sweep: [%s]\r", TextWaveToList(sweeps, ";", trailSep = 0)
 			printf "DAQ: [%s]\r", TextWaveToList(daqStates, ";", trailSep = 0)
 			printf "Testpulse: [%s]\r", TextWaveToList(tpStates, ";", trailSep = 0)
 			printf "Acquisition state: [%s]\r", TextWaveToList(acqStates, ";", trailSep = 0)
+			printf "Fifo position: [%s]\r", TextWaveToList(fifoPos, ";", trailSep = 0)
 			printf "Experiment: %s (%s)\r", GetExperimentName(), GetExperimentFileType()
 			printf "Igor Pro version: %s (%s)\r", GetIgorProVersion(), GetIgorProBuildVersion()
 			print "MIES version:"
@@ -284,6 +291,10 @@ threadsafe Function ASSERT_TS(variable var, string errorMsg, [variable extendedO
 	try
 		AbortOnValue var == 0, 1
 	catch
+#ifndef AUTOMATED_TESTING
+		AssertOnAndClearRTError()
+#endif // !AUTOMATED_TESTING
+
 		if(ParamIsDefault(extendedOutput))
 			extendedOutput = 1
 		else
@@ -319,7 +330,7 @@ threadsafe Function ASSERT_TS(variable var, string errorMsg, [variable extendedO
 			print stacktrace
 
 			print "~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~"
-			printf "Time: %s\r", GetIso8601TimeStamp(localTimeZone = 1)
+			printf "Time: %s\r", GetIso8601TimeStamp(localTimeZone = 1, numFracSecondsDigits = 3)
 			printf "Experiment: %s (%s)\r", GetExperimentName(), GetExperimentFileType()
 			printf "Igor Pro version: %s (%s)\r", GetIgorProVersion(), GetIgorProBuildVersion()
 			print "################################"

Packages/MIES/MIES_WaveDataFolderGetters.ipf

@@ -2218,7 +2218,7 @@ End
 /// - One for each entrySourceType, mapped via EntrySourceTypeMapper()
 threadsafe Function/WAVE GetLBRowCache(WAVE values)
 
-	variable actual, sweepNo, first, last
+	variable actual, sweepNo, first, last, expected
 	string key
 
 	variable versionOfNewWave = 6
@@ -2229,32 +2229,41 @@ threadsafe Function/WAVE GetLBRowCache(WAVE values)
 	WAVE/Z/D wv = CA_TryFetchingEntryFromCache(key, options = CA_OPTS_NO_DUPLICATE)
 
 	if(ExistsWithCorrectLayoutVersion(wv, versionOfNewWave))
-		if(actual == GetNumberFromWaveNote(wv, LABNOTEBOOK_MOD_COUNT))
+		expected = GetNumberFromWaveNote(wv, LABNOTEBOOK_MOD_COUNT)
+
+		// wave modification count tracking is only reliable while running
+		// inside a single experiment, not across experiments
+		if(actual == expected)
 			return wv
 		elseif(!MU_RunningInMainThread() && GetLockState(values) == 1)
 			return wv
 		else
-			// new entries were added so we need to propagate all entries to LABNOTEBOOK_GET_RANGE
-			// for sweep numbers >= than the currently acquired sweep
-			// this is required as the `last` element of the range can be changed if you add labnotebook
-			// entries and then query them and then add again.
-
-			if(IsNumericWave(values))
-				WAVE/Z sweeps = GetLastSweepWithSetting(values, "SweepNum", sweepNo)
-			elseif(IsTextWave(values))
-				WAVE/Z sweeps = GetLastSweepWithSettingText(values, "SweepNum", sweepNo)
-			endif
-
-			if(IsFinite(sweepNo))
-				EnsureLargeEnoughWave(wv, indexShouldExist = sweepNo, dimension = ROWS, initialValue = LABNOTEBOOK_GET_RANGE)
-				first = limit(sweepNo - 1, 0, Inf)
-				last  = sweepNo
-				Multithread wv[first, last][][] = LABNOTEBOOK_GET_RANGE
-
-				// now we are up to date
-				SetNumberInWaveNote(wv, LABNOTEBOOK_MOD_COUNT, actual)
-
-				return wv
+			if(actual > expected)
+				// new entries were added so we need to propagate all entries to LABNOTEBOOK_GET_RANGE
+				// for sweep numbers >= than the currently acquired sweep
+				// this is required as the `last` element of the range can be changed if you add labnotebook
+				// entries and then query them and then add again.
+
+				if(IsNumericWave(values))
+					WAVE/Z sweeps = GetLastSweepWithSetting(values, "SweepNum", sweepNo)
+				elseif(IsTextWave(values))
+					WAVE/Z sweeps = GetLastSweepWithSettingText(values, "SweepNum", sweepNo)
+				endif
+
+				if(IsFinite(sweepNo))
+					EnsureLargeEnoughWave(wv, indexShouldExist = sweepNo, dimension = ROWS, initialValue = LABNOTEBOOK_GET_RANGE)
+					first = limit(sweepNo - 1, 0, Inf)
+					last  = sweepNo
+					Multithread wv[first, last][][] = LABNOTEBOOK_GET_RANGE
+
+					// now we are up to date
+					SetNumberInWaveNote(wv, LABNOTEBOOK_MOD_COUNT, actual)
+
+					return wv
+				endif
+			else
+				// cache across experiments, so the stored wave modification is
+				// larger than the last labnotebook we cached, go for a full reset
 			endif
 		endif
 	else
@@ -2293,7 +2302,7 @@ End
 ///   could not be found, and #LABNOTEBOOK_UNCACHED_VALUE if the cache is empty.
 threadsafe Function/WAVE GetLBIndexCache(WAVE values)
 
-	variable actual, sweepNo, first, last
+	variable actual, sweepNo, first, last, expected
 	string key
 
 	variable versionOfNewWave = 5
@@ -2304,30 +2313,39 @@ threadsafe Function/WAVE GetLBIndexCache(WAVE values)
 	WAVE/Z/D wv = CA_TryFetchingEntryFromCache(key, options = CA_OPTS_NO_DUPLICATE)
 
 	if(ExistsWithCorrectLayoutVersion(wv, versionOfNewWave))
-		if(actual == GetNumberFromWaveNote(wv, LABNOTEBOOK_MOD_COUNT))
+		expected = GetNumberFromWaveNote(wv, LABNOTEBOOK_MOD_COUNT)
+
+		// wave modification count tracking is only reliable while running
+		// inside a single experiment, not across experiments
+		if(actual == expected)
 			return wv
 		elseif(!MU_RunningInMainThread() && GetLockState(values) == 1)
 			return wv
 		else
-			// new entries were added so we need to propagate all entries to uncached values
-			// for sweep numbers >= than the currently acquired sweep
-
-			if(IsNumericWave(values))
-				WAVE/Z sweeps = GetLastSweepWithSetting(values, "SweepNum", sweepNo)
-			elseif(IsTextWave(values))
-				WAVE/Z sweeps = GetLastSweepWithSettingText(values, "SweepNum", sweepNo)
-			endif
-
-			if(IsFinite(sweepNo))
-				EnsureLargeEnoughWave(wv, indexShouldExist = sweepNo, dimension = ROWS, initialValue = LABNOTEBOOK_UNCACHED_VALUE)
-				first = limit(sweepNo - 1, 0, Inf)
-				last  = sweepNo
-				Multithread wv[first, last][][] = LABNOTEBOOK_UNCACHED_VALUE
-
-				// now we are up to date
-				SetNumberInWaveNote(wv, LABNOTEBOOK_MOD_COUNT, actual)
-
-				return wv
+			if(actual > expected)
+				// new entries were added so we need to propagate all entries to uncached values
+				// for sweep numbers >= than the currently acquired sweep
+
+				if(IsNumericWave(values))
+					WAVE/Z sweeps = GetLastSweepWithSetting(values, "SweepNum", sweepNo)
+				elseif(IsTextWave(values))
+					WAVE/Z sweeps = GetLastSweepWithSettingText(values, "SweepNum", sweepNo)
+				endif
+
+				if(IsFinite(sweepNo))
+					EnsureLargeEnoughWave(wv, indexShouldExist = sweepNo, dimension = ROWS, initialValue = LABNOTEBOOK_UNCACHED_VALUE)
+					first = limit(sweepNo - 1, 0, Inf)
+					last  = sweepNo
+					Multithread wv[first, last][][] = LABNOTEBOOK_UNCACHED_VALUE
+
+					// now we are up to date
+					SetNumberInWaveNote(wv, LABNOTEBOOK_MOD_COUNT, actual)
+
+					return wv
+				endif
+			else
+				// cache across experiments, so the stored wave modification is
+				// larger than the last labnotebook we cached, go for a full reset
 			endif
 		endif
 	else

Packages/tests/Basic/UTF_Utils_System.ipf

@@ -131,7 +131,7 @@ static Function TestCacheBackupAndRestore()
 	DFREF dfr = GetCacheFolder()
 
 	name = GetListOfObjects(dfr, ".*")
-	CHECK_EQUAL_STR(name, "data;")
+	CHECK_EQUAL_STR(name, "data;keys;")
 
 	WAVE/Z/SDFR=dfr new = $StringFromList(0, name)
 	CHECK(!WaveRefsEqual(new, old))

Packages/tests/HardwareAnalysisFunctions/UTF_PatchSeqDAScale_Sub.ipf

@@ -2349,3 +2349,38 @@ static Function PS_DS_Sub11_REENTRY([string str])
 	CommonAnalysisFunctionChecks(str, sweepNo, setPassed)
 	CheckPSQChunkTimes(str, {20, 520, 2020, 2520})
 End
+
+static Function PS_DS_Sub12_preAcq(string device)
+
+	Make/FREE asyncChannels = {2, 3}
+	AFH_AddAnalysisParameter("PSQ_DaScale_Sub_DA_0", "AsyncQCChannels", wv = asyncChannels)
+
+	SetAsyncChannelProperties(device, asyncChannels, -1e6, +1e6)
+End
+
+// UTF_TD_GENERATOR DataGenerators#DeviceNameGeneratorMD1
+static Function PS_DS_Sub12([string str])
+
+	PS_DS_Sub2(str = str)
+End
+
+static Function PS_DS_Sub12_REENTRY([string str])
+
+	PS_DS_Sub2_REENTRY(str = str)
+
+	BackupCacheWaves()
+End
+
+// UTF_TD_GENERATOR DataGenerators#DeviceNameGeneratorMD1
+static Function PS_DS_Sub13([string str])
+
+	CA_FLushCache()
+	RestoreCacheWaves()
+
+	PS_DS_Sub2(str = str)
+End
+
+static Function PS_DS_Sub13_REENTRY([string str])
+
+	PS_DS_Sub2_REENTRY(str = str)
+End