When I Attempted To Invoke Stale Inventory Cleanup, Task IMTenantObsoleteInventoryMaintenance Ends With an Error

[mfeinman]

Hi all ...

The FlexNet Inventory Data Maintenance task on my DEV/TEST Application server is running into an error ever since I turned on stale inventory deletion.  My FNMS version is 2022R1.

The scheduled task runs the following command: 

cmd.exe /c ""C:\Program Files (x86)\Flexera Software\FlexNet Manager Platform\DotNet\bin\ShadowHostWin.exe" "BatchProcessTask.exe" run IMDataMaintenance & "C:\Program Files (x86)\Flexera Software\FlexNet Manager Platform\DotNet\bin\ShadowHostWin.exe" "BatchProcessTask.exe" run IMTenantDataMaintenance & "C:\Program Files (x86)\Flexera Software\FlexNet Manager Platform\DotNet\bin\ShadowHostWin.exe" "BatchProcessTask.exe" run IMTenantObsoleteInventoryMaintenance"

IMDataMaintenance and IMTenantDataMaintenance complete successfully.

IMTenantObsoleteInventoryMaintenance does not complete successfully, and I am unable to find any useful logs that can tell me what happened.  This is all I see.

BatchProcessScheduler.log:

2024-02-07 06:26:06,551 [endingMessageProcessor] [INFO ] Message IMTenantObsoleteInventoryMaintenance[4e8d0db3-7f6f-4ce0-8fc4-96bfdc823bcd] sent for processing

024-02-07 06:26:06,567 [ng.TaskStatusProcessor] [INFO ] Status[64e5b75e-4b7f-4ea8-9fac-439fa8c49158]: Task[4e8d0db3-7f6f-4ce0-8fc4-96bfdc823bcd]: received status update for task 'Processing' from processor MY-BATCH-PROCESSOR

2024-02-07 07:26:26,650 [ng.TaskStatusProcessor] [INFO ] Status[dc5b955f-7ecb-41cf-b1b2-bff256622bbb]: Task[4e8d0db3-7f6f-4ce0-8fc4-96bfdc823bcd]: received status update for task 'Error' from processor MY-BATCH-PROCESSOR

BatchProcessor.log

2024-02-07 06:26:06,551 [ocessor.BatchProcessor] [INFO ] IMTenantObsoleteInventoryMaintenance[4e8d0db3-7f6f-4ce0-8fc4-96bfdc823bcd] Executing task with process task type 'ProcessIMTenantObsoleteInventoryMaintenanceTask'

2024-02-07 06:26:06,551 [ventoryMaintenanceTask] [INFO ] IMTenantObsoleteInventoryMaintenance[4e8d0db3-7f6f-4ce0-8fc4-96bfdc823bcd] Processing cleaning obsolete inventory data

Unlike other tasks submitted through the batch processor, no completion or error message is displayed when the error occurs.  The only hint that an issue occurred is in the scheduler log.

I have also checked the SQL Server logs but there is nothing there.

Can some tell me how to turn on additional debugging for this process, or (if this is possible) identify what SQL script is being attempted so I can try running it myself in the database through SQL Server Management Studio and seeing what's going on?

--Mark

[tjohnson1]

It looks like you are hitting the 1 hour timeout for the task. There was a bug fixed in 2023 R1 for this behavior: https://community.flexera.com/t5/FlexNet-Manager-Suite-Known/Known-Issue-Batch-job-to-delete-obsolete-inventory-may-fail-with/ta-p/251015

You will need to disable the feature and implement the workaround to get through the initial deletion. You should then be able to enable the feature again to continue to delete inventory records as they age out.

[mfeinman]

Yes, I think you're right about the 1 hour timeout (which I didn't know about) because the timestamps are about an hour apart and the initial deletion will indeed delete a large amount of data.  I'll attempt this workaround and report back.  Thank you!

--Mark

[mfeinman]

Hi @tjohnson1 ...

As promised, I said I would report back after I attempted to run the script mentioned in the technote.

The script did run to completion and about 44,000 devices were deleted.

However, that seemed to push the timeout problem to the "import from staging" step during the Reconciliation process - specifically the part where File Evidence is deleted.  After the Reconciliation failed for the first time, I adjusted the FileEvidenceReaderBatchSize setting in the FNMSCompliance dbo.Configuration table down from 500,000 to 50,000.  That didn't make a difference - the Reconciliation process still failed.  I did notice, however, that the expected number of file evidence records to be deleted kept decreasing, and at some point, it decreased enough to where the timeout issue did not occur.  Here's a snapshot of the Reconciliation attempts:

Here's one of the failed entries expanded:

Here's the relevant log excerpt:

2024-02-11 02:31:17,160 [INFO ]     WriteFileEvidence - Load unmatched evidence
2024-02-11 02:32:31,733 [INFO ]       Successfully processed in 1 minute, 14 seconds
2024-02-11 02:32:31,733 [INFO ]     WriteFileEvidence - Insert unmatched evidence
2024-02-11 02:38:44,570 [INFO ]       Added 41 File Evidence records from the source database connections.
2024-02-11 02:38:44,570 [INFO ]       Successfully processed in 6 minutes, 12 seconds
2024-02-11 02:38:44,570 [INFO ]     WriteFileEvidence - Insert unmatched evidence mapping
2024-02-11 02:38:44,617 [INFO ]       Matched 82 records to File Evidence that was just added
2024-02-11 02:38:44,617 [INFO ]       Successfully processed in 0 seconds
2024-02-11 02:38:44,617 [INFO ]     WriteFileEvidence - Update local access modes
2024-02-11 02:38:44,617 [INFO ]       Updated 0 imported file evidence records to a local access mode
2024-02-11 02:38:44,617 [INFO ]       Successfully processed in 0 seconds
2024-02-11 02:38:44,617 [INFO ]     WriteInstalledFileEvidence
2024-02-11 02:48:15,801 [INFO ]       Identified 171309417 installed file evidence records
2024-02-11 02:48:15,801 [INFO ]       Successfully processed in 9 minutes, 31 seconds
2024-02-11 02:48:15,801 [INFO ]     WriteVDIInstalledFileEvidenceToTemplate
2024-02-11 02:48:15,848 [INFO ]       Identified 0 installed file evidence records on VDIs which will be mapped to templates
2024-02-11 02:48:15,848 [INFO ]       Successfully processed in 0 seconds
2024-02-11 02:48:15,848 [INFO ]     WriteVDIInstalledFileEvidence
2024-02-11 02:48:17,410 [INFO ]       Generated 0 VDI installed file evidence records
2024-02-11 02:48:17,410 [INFO ]       Successfully processed in 1 second
2024-02-11 02:48:17,410 [INFO ]     DeleteUnrequiredInstalledFileEvidence
2024-02-11 04:48:17,461 [INFO ]       Failed to execute Writer 'DeleteUnrequiredInstalledFileEvidence' from file C:\ProgramData\Flexera Software\Compliance\ImportProcedures\Inventory\Writer\FileEvidence.xml, at step line 1
Error: Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Operation cancelled by user.
Identified 70558193 InstalledFileEvidence rows to be deleted
The statement has been terminated.
2024-02-11 04:48:17,477 [INFO ]       All retries have been attempted for Writer 'DeleteUnrequiredInstalledFileEvidence'
2024-02-11 04:48:17,524 [ERROR]       System.Data.SqlClient.SqlException (0x80131904): Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Operation cancelled by user.
Identified 70558193 InstalledFileEvidence rows to be deleted
The statement has been terminated. ---> System.ComponentModel.Win32Exception (0x80004005): The wait operation timed out
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
   at System.Data.SqlClient.SqlCommand.RunExecuteNonQueryTds(String methodName, Boolean async, Int32 timeout, Boolean asyncWrite)
   at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion, String methodName, Boolean sendToPipe, Int32 timeout, Boolean& usedCache, Boolean asyncWrite, Boolean inRetry)
   at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
   at ManageSoft.Compliance.Importer.Logic.XML.Writer.Execute(IExecutionContext context)
   at ManageSoft.Compliance.Importer.Logic.ComplianceImporter.ExecuteWriters(ComplianceReader p_ComplianceReader, IExecutionContext context, String singleConnectionIdentifier)
ClientConnectionId:4ac44ca0-4f27-442c-968d-3e04a966763b
Error Number:-2,State:0,Class:11

The timeout occurred after exactly 2 hours.

This was a DEV system where I can afford to have errors like this, but I can't have this in Production.  

Was there any additional database configuration I should have made (like adjusting "FileEvidenceWriterBatchSize" down from its default of 100,000)?

I suppose an alternative here would be to run the deletion script on far fewer devices, then let the Reconcile finish, then repeat until the devices in the initial cleanup are all deleted?

--Mark

[tjohnson1]

Yes, so once the inventory records are deleted the Import into Staging step then handles deleting the evidence linked to those deleted devices.

You can extend the timeout in the registry on your batch server (HKLM\SOFTWARE\Wow6432Node\ManageSoft Corp\ManageSoft\Compliance\CurrentVersion\CommandTimeout) or as you saw allow it to run multiple times.

Another option once the initial import fails, is to run the following SQL against your Compliance DB to delete the file evidence of the no longer present devices. You will need to find the ComplianceConnectionID (from the ComplianceConnection table) for the FlexNet Manager Suite connection and replace that ID in the script wherever ComplianceConnectionID is referenced.

-- Clearing out records from ImportedInstalledFileEvidence for ComplianceConnectionID of 4 - FlexNet Manager Suite Where the ImportedComputer record no longer exists
-- Set up to delete 1,000,000 at a time and there are around 59M records.
IF OBJECT_ID('tempdb..#ExternalIDsToKeep') IS NOT NULL
    DROP TABLE #ExternalIDsToKeep
GO
CREATE TABLE #ExternalIDsToKeep
(
    ExternalID BIGINT PRIMARY KEY
)
INSERT INTO #ExternalIDsToKeep (ExternalID)
SELECT ExternalID FROM ImportedComputer WHERE ComplianceConnectionID=4
WHILE EXISTS (SELECT TOP 1 * FROM dbo.ImportedInstalledFileEvidence i LEFT OUTER JOIN #ExternalIDsToKeep e ON i.ExternalID = e.ExternalID WHERE i.ComplianceConnectionID = 4 AND e.ExternalID IS NULL)
BEGIN
    DELETE TOP (1000000) i FROM
        dbo.ImportedInstalledFileEvidence i
        LEFT OUTER JOIN #ExternalIDsToKeep e 
        ON i.ExternalID = e.ExternalID 
    WHERE i.ComplianceConnectionID = 4 AND e.ExternalID IS NULL
END
IF OBJECT_ID('tempdb..#ExternalIDsToKeep') IS NOT NULL
    DROP TABLE #ExternalIDsToKeep

[mfeinman]

Hi @tjohnson1 ... thanks for the deletion script for file evidence.

I'll give that a try and report back. (Since it's a DEV environment, I can restore the PROD data and do this again.)

--Mark

[mfeinman · Accepted solution]

Hi @tjohnson1 ...

As promised, I'm closing the loop on this one.

I basically deleted devices in roughly 10K batches. To come up with the number of devices to delete, I used this query:

-- Query to determine the number of computers that haven't sent inventory
-- in some number of days.  Set the variable "@ObsoleteInventoryPeriodInDays"
-- to the number of days that you want to examine.

DECLARE	@ObsoleteInventoryPeriodInDays INT = 60
DECLARE @staleDate DATETIME = DATEADD(day, -@ObsoleteInventoryPeriodInDays, DATEDIFF(Day, 0, GetDate()))

-- Use this query to get a total number of devices
SELECT count(c.ComputerID) as DeviceCountToBeDeleted
FROM FNMSInventory.dbo.Computer c 
	INNER JOIN FNMSInventory.dbo.InventoryReport ir ON c.ComputerID = ir.ComputerID
WHERE ir.HWDate < @staleDate

I ran the first script to delete the devices from inventory and then let the Reconciliation delete the file evidence records.  Both sections took about an hour each and the Reconciliation time did not increase by much at all.

I cleaned up the first script a bit.  When it ran, it displayed lots of messages about how many records were affected but it didn't give me any sense of how far through the process it was.  I modified the script to suppress those "xx records affected" messages and to display meaningful messages that gave me an indication of how long the script will run.  For example:

09:22:51: Starting the Stale Deletion Script ...
09:22:51: Computers that have not reported inventory from Jan 13 2024 or before (60 or more days ago) will be deleted.
09:22:51: Approximately 866 script iterations will be necessary to delete 8656 computers.
 
09:23:19: 1 of 866 script iterations complete.
 
09:23:25: 2 of 866 script iterations complete.

....

10:33:17: 865 of 866 script iterations complete.
 
10:33:19: 866 of 866 script iterations complete.
 
10:33:19: Elapsed time - 70.47 minutes.
10:33:19: The Stale Deletion Script has completed successfully.

Here's my revised script based on the one you supplied:

-- ----------------------------------------------------------------------------------------------
-- Procedure to delete computers that haven't reported inventory in XX days.
-- Set the variable @ObsoleteInventoryPeriodInDays to define "stale inventory".
--
-- There could be a deplay in displaying the PRINT statements as they appear to be
-- cached somehow.  It seems to start after 250 iterations of the RAISERRR statement.
-- ----------------------------------------------------------------------------------------------

-- Measure elapsed time
DECLARE @StartTime datetime
DECLARE @EndTime datetime
Set @StartTime=GETDATE() 

PRINT CONVERT (varchar(30), getdate(),  + ': Starting the Stale Deletion Script ...'
SET NOCOUNT ON			-- No need to see "xx computers affected" after each deletion step

-- Set this variable to define "stale inventory"
DECLARE	@ObsoleteInventoryPeriodInDays INT = 60

-- Convert the threshold into a date
DECLARE @staleDate DATETIME = DATEADD(day, -@ObsoleteInventoryPeriodInDays, DATEDIFF(Day, 0, GetDate()))
PRINT CONVERT (varchar(30), getdate(),  + ': Computers that have not reported inventory from ' + 
	CAST(@staleDate as varchar(11)) + ' or before (' + CAST(@ObsoleteInventoryPeriodInDays as varchar(10)) + 
	' or more days ago) will be deleted.'

DECLARE @BatchSize INT = 10			-- How many devices to delete in one SQL transaction
DECLARE @IterationCount INT = 0		-- How many times the loop below has executed
DECLARE @TotalIterations INT = 0	-- How many times the loop below will execute
DECLARE @DeletionCount INT = 0		-- How many devices will be deleted

-- Get the number of devices that will be deleted
SELECT @DeletionCount = COUNT(c.ComputerID) 
FROM FNMSInventory.dbo.Computer c 
	INNER JOIN FNMSInventory.dbo.InventoryReport ir ON c.ComputerID = ir.ComputerID
WHERE ir.HWDate < @staleDate

SET @TotalIterations = (@DeletionCount / @BatchSize) + 1

PRINT CONVERT (varchar(30), getdate(),  + ': Approximately ' + CAST(@TotalIterations as varchar(10)) +
	' script iterations will be necessary to delete ' + CAST(@DeletionCount as varchar(10)) +
	' computers.'
RAISERROR(N'', 0, 1) WITH NOWAIT	-- Display above messages in a more immediate fashion

CREATE TABLE #Computer (ComputerID BIGINT)

WHILE 1 = 1
BEGIN
	-- Get the devices that will be deleted in this transaction and place
	-- them into a "process me" temporary table
	INSERT INTO #Computer
	SELECT TOP (@BatchSize) c.ComputerID 
	FROM FNMSInventory.dbo.Computer c 
		INNER JOIN FNMSInventory.dbo.InventoryReport ir ON c.ComputerID = ir.ComputerID
	WHERE ir.HWDate < @staleDate

	-- Delete the devices as a single SQL transaction
	BEGIN TRANSACTION

	IF EXISTS(SELECT 1 from #Computer )
		EXEC FNMSInventory.dbo.DeleteComputers

	COMMIT TRANSACTION
	
	-- Summarize results of this iteration
	SET @IterationCount += 1
	PRINT CONVERT (varchar(30), getdate(),  + ': ' + CAST(@IterationCount as varchar(10)) + 
		' of ' + CAST(@TotalIterations as varchar(10)) + ' script iterations complete.'
	RAISERROR(N'', 0, 1) WITH NOWAIT	-- Display messages in a more immediate fashion
		
	-- Remove the devices from the "just processed" list
	DELETE FROM #Computer	
	IF @@ROWCOUNT < @BatchSize BREAK
END
	
-- Drop the "process me" table
DROP TABLE #Computer

-- And we're done.
SET NOCOUNT OFF			-- Restore the default

Set @EndTime=GETDATE()

DECLARE @ElapsedTime DECIMAL(5,2) = 0.0
SET @ElapsedTime = ROUND((DATEDIFF(SS, @StartTime, @EndTime) / 60.0), 2)
PRINT CONVERT (varchar(30), getdate(),  + ': Elapsed time - ' + CAST(@ElapsedTime as varchar(10)) + ' minutes.'
PRINT CONVERT (varchar(30), getdate(),  + ': The Stale Deletion Script has completed successfully.'

Hopefully others will find this revision useful.

Edit: Interesting that some of my SQL is being displayed as a smiling face with sunglasses - it didn't do that when I previewed it!

--Mark