Problems with Cache

Question

I am running CM v1910
Lately I have been having widespread trouble with package caching on client machines.
When I push out a package set to download and run, I am having a fail rate of ~10%.
Looking in the CAS.LOG, I can see that the download is working and I can see the content hash succeeded which proves the content is on the client - but it never makes it into the cache.

Download completed for content HLT0048F.8 under context System  ContentAccess   9/16/2020 3:54:11 PM    6984 (0x1B48)
Hash verification succeeded for content HLT0048F.8 downloaded under context System  ContentAccess   9/16/2020 3:54:12 PM    6984 (0x1B48)
Saved Content ID Mapping HLT0048F.8, C:\WINDOWS\ccmcache\f  ContentAccess   9/16/2020 3:54:12 PM    6984 (0x1B48)
CacheManager: ADD new cache entry for id:HLT0048F Version : 8 Size : 33846K RefCount:1 LastRef Minutes : 0 State : ACTIVE PinDuration : 15058 Location : C:\WINDOWS\ccmcache\f  ContentAccess   9/16/2020 3:54:12 PM    6984 (0x1B48)
Download succeeded for download request {C99E38DA-90AA-4A7D-B052-66B1957D905A}  ContentAccess   9/16/2020 3:54:12 PM    6984 (0x1B48)
Error: DeleteDirectory:- Failed to delete Directory  with Error 0x00000003. ContentAccess   9/16/2020 3:54:12 PM    6984 (0x1B48)
Saved Content ID Mapping HLT0048F.8, C:\WINDOWS\ccmcache\f  ContentAccess   9/16/2020 3:54:13 PM    6308 (0x18A4)

But then over in the execmgr.log the content cant be located and looking in CCMCache there is no "f" folder.

I can often just use clientcenter to force the advertisement to rerun and the download/cache/run will succeed -- though it will be cached in the next higher folder ie "g"

Looking in the c:\windows\ccmcache\ it just skips over that failed "f" caching attempt and the files are all just fine in "g"

The security team swears that they have excluded C:\windows\ccmcache from AV scans - that is the first thing I thought of - and there are no records of blocked files in any AV logs.

In execmgr.log when it fails I get this error.

MTC signaled SWD execution request with program id: I-Install software, package id: HLT0048F for execution. execmgr 9/16/2020 3:54:13 PM 6308 (0x18A4)
GetContentRequest failed 0x87d01107 execmgr 9/16/2020 3:54:13 PM 6308 (0x18A4)

when it works, I see

MTC signaled SWD execution request with program id: I-Install Software, package id: HLT0048F for execution. execmgr 9/16/2020 3:57:20 PM 8720 (0x2210)
Sending ack to MTC for task with id: {628DEF35-F85E-4E38-BF3B-D7821935CE4D} execmgr 9/16/2020 3:57:20 PM 8720 (0x2210)
Executing program Install.exe in Admin context execmgr 9/16/2020 3:57:20 PM 8720 (0x2210)

It feels like a timing problem of some kind and it is driving me a little crazy. For large deployments - it is really tedious to have to attempt to rerun on all the fail to cache. I am tempted to just use run from DP on things and avoid the cache all together.

I cant think of any recent changes that might be interfering. I would think if there was an AV problem, then the files would get stopped at the temp folder and would not Hash correctly. That they are hashing right shows the client is downloading the files and the files are making it to the local disk intact and correct. So whats going on with not copying into the assigned ccmcache subfolder?

Anyone with ideas?

Answer 1

@ToddMiller-7887

Could we change the configuration of our looging options like enabling the verbose log?If there is a problem,then we will see more details in the log after we change the logging options.
For more details,please refer to this article:
https://learn.microsoft.com/en-us/mem/configmgr/core/plan-design/hierarchy/about-log-files#bkmk_reg-client

---

If the response is helpful, please click "Accept Answer" and upvote it.
Note: Please follow the steps in our documentation to enable e-mail notifications if you want to receive the related email notification for this thread.

Answer 2

I turned on verbose logging. I am not sure it has helped to locate the problem, but I did find something in the CAS log.
With global verbose logging enabled and using CMtrace to merge CAS, exec, and DTS logs... When the caching fails, this appears in the log -- no lines between these two lines.

Saved Content ID Mapping HLT003BD.1, C:\WINDOWS\ccmcache\d ContentAccess 9/17/2020 9:42:13 AM 10552 (0x2938)
Removed Content ID Mapping for HLT003BD.1 ContentAccess 9/17/2020 9:42:14 AM 10552 (0x2938)

I looked back through the merged logs and there are no other instances of "Removed Content ID Mapping"
This line only appears on the failure.

I tried pushing 5 packages to this client all cached correctly and executed successfully. Then on this 5th package, I finaly got a failure. Rerunning the same advert/package on the client using the clientcenter succeeded.

Something in the client process appears to be removing the content one second after saving it?

I am attaching a "success" and "failure" log. The lines look basically the same... there appears to be a race condition between the cache manager and the signal to the execmgr. Like the execmgr tries to execute the process prior to cachemgr fully releasing it for execution.25578-failure.txt25579-success.txt

When the "MTC signaled SWD execution request with program id:" in execmgr.log happens BEFORE "Saved Content ID Mapping" in CAS.log there is a failure. And there is an extra line "Removed Content ID Mapping" -

When CAS reports "saved content ID mapping" BEFORE execmgr reports "MTC signaled SWD execution" the process succeeds.

Answer 3

@ToddMiller-7887

Could we know whether the failed client is stable or random?
If the client is stable,maybe we could try to uninstall and then reinstall it.Maybe we could cache it to see if it works.

---

If the response is helpful, please click "Accept Answer" and upvote it.
Note: Please follow the steps in our documentation to enable e-mail notifications if you want to receive the related email notification for this thread.

Answer 4

I don’t understand. As I stated, this is a widespread problem across all endpoints. A client will cache and install multiple packages in a row and then fail as shown. Also, I stated that a retry via client center will usually result in a success. When I push a package to 1000 clients I can expect the cache to fail on about 9% of clients. It is not a broken client as this problem is not isolated to a particular package or client. It is random packages and random clients And the fail rate is ~9%
The downloaded package downloads into a working temp folder, hashes OK, and then fails to copy into the final cache sub-folder.

Answer 5

I don't know if this is a contributing factor or not, but the instances where this happens, the client is being added to a collection that has an advertisement that happens in the past.

So there could be a package/program to install Chrome browser. There is an advertisement to "collection A" that has a mandatory install time of Feb 2, 2020 (some time in the past.)
In September - long after the advertisement mandatory time, clients are added to "Collection A" or a query rule adds them to Collection A. This force the client, on its next policy refresh to learn that it has an active advertisement assignment and the client needs to download and run a package/program right away.

In cases where the mandatory advertisement is in the future, where the client may pre-cache but is not set to run the advertisement until some time later, we do not see this problem.