A couple of days ago I looked in detail at the Content Caching server in Big Sur, and showed some examples of its transactions in the log. This article follows on from that, and shows what happens when the server is asked for a macOS security data update, and how it supplies cached updates for apps from the Mac App Store. If you don’t recall how the latter works, this article explains it in detail, again with extensive references to log entries.

softwareupdate

To assess how the Content Caching server delivers macOS software updates, a client on the same local network ran the command to fetch and install all available updates for that Mac from within SilentKnight. The command used was
softwareupdate -ia --include-config-data

Two updates were available, to MRT and XProtect, which were listed and downloaded automatically by that command. That process consisted of two requests for each of the available updates, a HEAD request to identify the availability and size of the update, and a GET request to download it from the cache.

The HEAD request was logged on the Content Caching server thus:
Received HEAD request by "Software Update" for /content/downloads/…/MRTConfigData_10_15.pkg
ECAssetHandler[0x7fce2ca3de10]: Asset /content/downloads/…/MRTConfigData_10_15.pkg, path /Volumes/ThunderBay4/Library/Application Support/Apple/AssetCache/Data/…, cached length 4830957, MD5 (null), last-modified Mon, 24 May 2021 17:51:34 GMT, extents [0,4830957]
ECAssetRequestor[0x7fce2cb60bf0]: Issuing outgoing If-Modified-Since request for URL http://swcdn.apple.com/content/downloads/…/MRTConfigData_10_15.pkg
ECResponse[0x7fce2cb23d70]: Info loaded: response code = 304, reason code = 10, file length = 4830957, reader = 0x7fce2ca28720
ECAssetRequestor[0x7fce2cb60bf0]: Closing connection after 304 response to If-Modified-Since
ECAssetRequestor[0x7fce2cb60bf0]: Connection closed by source at offset 0/-1
Served 0 bytes of 4.8 MB; 0 bytes from cache, 0 bytes stored from Internet, 0 bytes from peers, 0 bytes from parents
ECCacheReader[0x7fce2ca28720]: canceled at offset = 0
ECAssetHandler[0x7fce2ca3de10]: Removed reader 0x7fce2ca28720 at 0/-1, readers [], requestors [], will cancel 0 requestors >= 0 for asset /content/downloads/…/MRTConfigData_10_15.pkg
Since server start at 2021-06-13 09:07:05.427: 600.5 MB returned to clients, 0 bytes to peers, 0 bytes to children; 40.0 MB stored from Internet, 0 bytes from peers, 0 bytes from parents; 67.6 MB imported.

That confirmed with Apple’s update server at swcdn.apple.com that the cached version was current, but didn’t download it. That was followed immediately by the GET request to download that update from the caching server:
Received GET request by "Software Update" for /content/downloads/…/MRTConfigData_10_15.pkg
ECAssetHandler[0x7fce2a5765f0]: Asset /content/downloads/…/MRTConfigData_10_15.pkg, path /Volumes/ThunderBay4/Library/Application Support/Apple/AssetCache/Data/…, cached length 4830957, MD5 (null), last-modified Mon, 24 May 2021 17:51:34 GMT, extents [0,4830957]
ECAssetRequestor[0x7fce2a61e500]: Issuing outgoing If-Modified-Since request for URL http://swcdn.apple.com/content/downloads/…/MRTConfigData_10_15.pkg
ECResponse[0x7fce2a575190]: Info loaded: response code = 304, reason code = 10, file length = 4830957, reader = 0x7fce2cb20480
ECAssetRequestor[0x7fce2a61e500]: Closing connection after 304 response to If-Modified-Since
ECAssetRequestor[0x7fce2a61e500]: Connection closed by source at offset 0/-1
ECAssetHandler[0x7fce2a5765f0]: Opened extent [0,4830957] for reading at offset 0 (offset into file = 0)
Served all 4.8 MB of 4.8 MB; 4.8 MB from cache, 0 bytes stored from Internet, 0 bytes from peers, 0 bytes from parents
ECCacheReader[0x7fce2cb20480]: canceled at offset = 4830957
ECAssetHandler[0x7fce2a5765f0]: Removed reader 0x7fce2cb20480 at 4830957/-1, readers [], requestors [], will cancel 0 requestors >= 0 for asset /content/downloads/…/MRTConfigData_10_15.pkg
Since server start at 2021-06-13 09:07:05.427: 606.3 MB returned to clients, 0 bytes to peers, 0 bytes to children; 40.0 MB stored from Internet, 0 bytes from peers, 0 bytes from parents; 67.6 MB imported.

softwareupdate then installed the two updates.

Mac App Store update

Four updates of apps obtained from the Mac App Store were then performed using the App Store app on the client Mac, and observed in that client’s logs, and those of the Content Caching server. There was no involvement of the local caching server until the sub-systems supporting the App Store app came to download the update itself. To distinguish log entries, rather than set both in ‘code’, entries on the caching server are shown in bold, and those on the client in italics.

On the client, pre-flight is downloaded direct from Apple’s server:
Downloading remote pre-flight from https://osxapps.itunes.apple.com/itunes-assets/Purple115/v4/a8/f2/58/….pfpkg

The disk space check is performed as usual. The size given here as fileSize matches that on the caching server:
Disk space check: 373740396544 bytes available, 22085110562 bytes recoverable, 0 bytes downloaded, 1247827572 bytes required (installSize=800344064 + fileSize=132910708 + paddingSize=314572800)

It’s the .pkg download which is turned into a Local Data Task against the IP address of the caching server:
Will download package using request: … { URL: https://osxapps.itunes.apple.com/itunes-assets/Purple115/v4/48/80/ac/….pkg }
Created task: LocalDataTask … in session: (null) for URL: http://192.168.63.3:52613/itunes-assets/Purple115/v4/48/80/ac/….pkg?source=osxapps.itunes.apple.com&sourceScheme=https
Task: LocalDataTask … will send request

This task is received on the caching server as a GET transaction, and is checked against Apple’s server to ensure that the cached update is the latest:
Received GET request by “MacAppStore/3.0” for /itunes-assets/Purple115/v4/48/80/ac/….pkg
ECAssetHandler[0x7fce2ca383a0]: Asset /itunes-assets/Purple115/v4/48/80/ac/….pkg, path /Volumes/ThunderBay4/Library/Application Support/Apple/AssetCache/Data/…, cached length 132910708, MD5 (null), last-modified Tue, 25 May 2021 22:01:33 GMT, extents [0,132910708]
ECAssetRequestor[0x7fce2c809ab0]: Issuing outgoing If-Modified-Since request for URL https://osxapps.itunes.apple.com/itunes-assets/Purple115/v4/48/80/ac/….pkg
ECResponse[0x7fce2a4557d0]: Info loaded: response code = 304, reason code = 10, file length = 132910708, reader = 0x7fce2ca41fe0
ECAssetRequestor[0x7fce2c809ab0]: Closing connection after 304 response to If-Modified-Since
ECAssetRequestor[0x7fce2c809ab0]: Connection closed by source at offset 0/-1

The client received that response. Note that this entry again gives the IP address of the caching server, and reports the size of the update, which matches that expected:
Received response: … { URL: http://192.168.63.3:52613/itunes-assets/Purple115/v4/48/80/ac/….pkg?source=osxapps.itunes.apple.com&sourceScheme=https } { Status Code: 200, Headers {
…
“Content-Length” = (
132910708
); …
Started transaction: com.apple.appstored.AssetTask:UPD15DDADA9/com.apple.iWork.Keynote:409183694/72EE75B9-2
Setting progress: 0.00 for bundleID: com.apple.iWork.Keynote
That final entry sets the progress circle in the app window at the start position, and is followed by frequent updates which advance it round the circle.

The server starts to deliver the update over the network:
ECAssetHandler[0x7fce2ca383a0]: Opened extent [0,132910708] for reading at offset 0 (offset into file = 0)

Three seconds later, the server has delivered the whole of the update to the client, and finished the transaction:
Served all 132.9 MB of 132.9 MB; 132.9 MB from cache, 0 bytes stored from Internet, 0 bytes from peers, 0 bytes from parents
ECCacheReader[0x7fce2ca41fe0]: canceled at offset = 132910708
ECAssetHandler[0x7fce2ca383a0]: Removed reader 0x7fce2ca41fe0 at 132910708/-1, readers [], requestors [], will cancel 0 requestors >= 0 for asset /itunes-assets/Purple115/v4/48/80/ac/….pkg
Since server start at 2021-06-13 09:07:05.427: 791.4 MB returned to clients, 0 bytes to peers, 0 bytes to children; 40.0 MB stored from Internet, 0 bytes from peers, 0 bytes from parents; 67.6 MB imported.
That marks the end of the involvement of the Content Caching server.

At this stage on the client, the progress circle has reached the 80% completed position, at which point rapid movement ceases while it installs the update. The Local Data Task is thus reported complete:
Setting progress: 0.80 for bundleID: com.apple.iWork.Keynote
Response body bytes received speed: 40859269
Completed task: LocalDataTask …

Once the post-download phase is complete, and the app has been fully updated, the progress circle reaches the top, and Crossfire declares the updated app has been installed:
Setting progress: 1.00 for bundleID: com.apple.iWork.Keynote
[Crossfire] Apps installed: [com.apple.iWork.Keynote]

These stages are easily observed by watching the progress circle. When it first appears, with progress at 0%, there’s the initial pause for the pre-flight phase to be completed with Apple’s servers, as detailed here. Once that’s complete, delivery of the update is accompanied by very rapid progress until the circle reaches 80% complete, or roughly 9:30 on the clock. The final installation and other post-download actions are significantly slower, even for small apps and updates, and aren’t accelerated by the Content Caching server, which has by then completed its task.

I hope these annotated log extracts add depth to understanding of both how the Content Caching server works, and how App Store updates are installed.