Nov 01 2022 01:01 AM - edited Nov 01 2022 01:39 AM
Hi,
We are experiance a strange case of problems related to clients that are not running or updating hardware inventory.
We see the following errors in InventoryAgent.log:
Inventory: *********************** Start of message processing. *********************** InventoryAgent 01-11-2022 07:29:00 10500 (0x2904)
Inventory: Message type is InventoryAction InventoryAgent 01-11-2022 07:29:00 10500 (0x2904)
Inventory: Temp directory = C:\WINDOWS\CCM\Inventory\Temp\ InventoryAgent 01-11-2022 07:29:00 10500 (0x2904)
Inventory: Clearing old collected files. InventoryAgent 01-11-2022 07:29:00 10500 (0x2904)
Inventory: Opening store for action {00000000-0000-0000-0000-000000000001} ... InventoryAgent 01-11-2022 07:29:00 10500 (0x2904)
CInvState::VerifyInventoryVersionNumber: Mismatch found for '{00000000-0000-0000-0000-000000000001}': 5.4 vs. 0.0 InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Inventory: Version number mismatch; will do a Full report. InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Inventory: (80004005) InventoryAction does not exist () InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Raising event:
[SMS_CodePage(850), SMS_LocaleID(1030)]
instance of CLIMSG_HINV_ERROR_COLLECTIONFAILURE
{
ClientID = "GUID:307BF58C-B6B5-4929-8A9E-A942EABEE0B1";
Data1 = "0";
Data2 = "0";
Data3 = "";
DateTime = "20221101062930.160000+000";
InventoryActionID = "{00000000-0000-0000-0000-000000000001}";
MachineName = "Computer1";
ProcessID = 20316;
SiteCode = "xxx";
ThreadID = 10500;
};
InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
CInvState:Init: ReadInventoryActionPolicy() failed: 80004005 InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Inventory: Initialization completed in 30.141 seconds InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Inventory: Cycle completed in 30.141 seconds InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Inventory: Action completed. InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
Inventory: ************************ End of message processing. ************************ InventoryAgent 01-11-2022 07:29:30 10500 (0x2904)
I have some sort of narrowed it down to the configuration.mof file. As everytime I do change the mof file, version is ofcause updated in SCCM:
PolicyID Version DeviceVersion Body DeviceBody PolicyFlags PolicyPriority DeviceBodySignature PolicyType PolicyHash
{0410cabb-fce9-41d0-92bd-3ac9fd8173aa} 77.00 NULL {BASE64/CONFIRATION.MOF} NULL 0 25 NULL NULL NULL
Then the client on the next policy update retrieves policy and evaluate and a new hardware invetory action is succesfully sended and proccesed at SCCM.
But the errors and missing hardware inventory starts begins again the next day.
Where to start throubleshooting this problem?
Best Regards
Thomas Nissen
Nov 01 2022 05:15 AM
Nov 18 2022 03:57 AM
SolutionHi again,
I now seem to have solved the problem, at least there have been hardware inventory 3 days without problems now.
First I replaced the configuration.mof with the default installation, removed alle Client Policies related to hardware inventory, and cleared all inventory classes from Default Client Settings.
Created a new inventory from scratch.
That did unfortunally not solve the problem 😞
After a change in configuration.mof and after creating/editing the Client Policies related to Hardware Inventory the hardware inventory worked like a charm, for appromately 6-12 hours.
After that the log again showed the errors in InventoryAgent.log: CLIMSG_HINV_ERROR_COLLECTIONFAILURE and no hardware inventory processed.
Okay, the next step was then to find out exactly what happends from the time where the hardware inventory worked and where it not worked.
I then took a test client and set the LogLevel = 0 (Debug), LogMaxHistory = 5 and LogMaxSize = 50MB in HKLM:\SOFTWARE\Microsoft\CCM\Logging\@Global
And set up a powershell script running a hardware inventory every 30 mins.
Now i catched the error and could look at other logfiles in the same time period.
So now I did see the errors in appearing and could see the logs in PolicyAgent.log.
And to my big surprise the client receives a PolicyAssignment with Action=Delete
Total 1 PolicyAssignment(s) found. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Successfully retrieved Site Server Signing Certificate from the registry. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Successfully created certificate context. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Validating PolicyAssignment '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}'. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
PolicyAssignment:<PolicyAssignment Action="Delete" PolicyAssignmentID="{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}" PolicyID="{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}"/> PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Policy Body :<PolicyAssignment Action="Delete" PolicyAssignmentID="{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}" PolicyID="{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}"/> PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Delta policy update PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Received Machine delta policy update with 1 assignments PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Deleting policy assignment '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}' PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Revoking policy '{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}' version '97.00' on '\\.\ROOT\ccm\policy\machine\requestedconfig' PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Processing policy rule {664329be-6f53-477b-9e82-ac430d9627ce} PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Revoking policy rule {664329be-6f53-477b-9e82-ac430d9627ce} PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Need to revoke rule PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Rule state was not inactive: Active PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
!sTempString.empty(), HRESULT=80070057 (C:\__w\1\s\src\Framework\Core\CCMCore\String.cpp,1125) PolicyAgent_RequestAssignments 14-11-2022 21:57:30 7984 (0x1F30)
[PolicyUpdate] Marked 'ccm_scheduler_scheduledmessage.scheduledmessageid="{00000000-0000-0000-0000-000000000001}"' deleted. PolicyAgent_RequestAssignments 14-11-2022 21:57:30 7984 (0x1F30)
So what is this all about. The policy is getting revoked and action is deleted 😞
When looking at the SQL:
SELECT * FROM PolicyAssignment WHERE PolicyAssignmentID = '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}'
Sure the IsTombstoned = 1 and the TombstoneBody exactly included the:
<PolicyAssignment Action="Delete" PolicyAssignmentID="{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}" PolicyID="{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}"/>
I updated the PolicyAssignment to IsTombstoned = 0:
UPDATE PolicyAssignment SET IsTombstoned = 0 WHERE PolicyAssignmentID = '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}"
And after that I updated the configuration.mof to update the record and create a new version.
The problem is now solved.
Best Regards
Thomas Nissen
Nov 18 2022 03:57 AM
SolutionHi again,
I now seem to have solved the problem, at least there have been hardware inventory 3 days without problems now.
First I replaced the configuration.mof with the default installation, removed alle Client Policies related to hardware inventory, and cleared all inventory classes from Default Client Settings.
Created a new inventory from scratch.
That did unfortunally not solve the problem 😞
After a change in configuration.mof and after creating/editing the Client Policies related to Hardware Inventory the hardware inventory worked like a charm, for appromately 6-12 hours.
After that the log again showed the errors in InventoryAgent.log: CLIMSG_HINV_ERROR_COLLECTIONFAILURE and no hardware inventory processed.
Okay, the next step was then to find out exactly what happends from the time where the hardware inventory worked and where it not worked.
I then took a test client and set the LogLevel = 0 (Debug), LogMaxHistory = 5 and LogMaxSize = 50MB in HKLM:\SOFTWARE\Microsoft\CCM\Logging\@Global
And set up a powershell script running a hardware inventory every 30 mins.
Now i catched the error and could look at other logfiles in the same time period.
So now I did see the errors in appearing and could see the logs in PolicyAgent.log.
And to my big surprise the client receives a PolicyAssignment with Action=Delete
Total 1 PolicyAssignment(s) found. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Successfully retrieved Site Server Signing Certificate from the registry. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Successfully created certificate context. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Validating PolicyAssignment '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}'. PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
PolicyAssignment:<PolicyAssignment Action="Delete" PolicyAssignmentID="{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}" PolicyID="{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}"/> PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Policy Body :<PolicyAssignment Action="Delete" PolicyAssignmentID="{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}" PolicyID="{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}"/> PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Delta policy update PolicyAgent_RequestAssignments 14-11-2022 21:57:26 7984 (0x1F30)
Received Machine delta policy update with 1 assignments PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Deleting policy assignment '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}' PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Revoking policy '{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}' version '97.00' on '\\.\ROOT\ccm\policy\machine\requestedconfig' PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Processing policy rule {664329be-6f53-477b-9e82-ac430d9627ce} PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Revoking policy rule {664329be-6f53-477b-9e82-ac430d9627ce} PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Need to revoke rule PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
Rule state was not inactive: Active PolicyAgent_RequestAssignments 14-11-2022 21:57:27 7984 (0x1F30)
!sTempString.empty(), HRESULT=80070057 (C:\__w\1\s\src\Framework\Core\CCMCore\String.cpp,1125) PolicyAgent_RequestAssignments 14-11-2022 21:57:30 7984 (0x1F30)
[PolicyUpdate] Marked 'ccm_scheduler_scheduledmessage.scheduledmessageid="{00000000-0000-0000-0000-000000000001}"' deleted. PolicyAgent_RequestAssignments 14-11-2022 21:57:30 7984 (0x1F30)
So what is this all about. The policy is getting revoked and action is deleted 😞
When looking at the SQL:
SELECT * FROM PolicyAssignment WHERE PolicyAssignmentID = '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}'
Sure the IsTombstoned = 1 and the TombstoneBody exactly included the:
<PolicyAssignment Action="Delete" PolicyAssignmentID="{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}" PolicyID="{0410cabb-fce9-41d0-92bd-3ac9fd8173aa}"/>
I updated the PolicyAssignment to IsTombstoned = 0:
UPDATE PolicyAssignment SET IsTombstoned = 0 WHERE PolicyAssignmentID = '{94f96cf0-7f5a-4fd3-8385-f3ad71187df6}"
And after that I updated the configuration.mof to update the record and create a new version.
The problem is now solved.
Best Regards
Thomas Nissen