softwareupdate, SUS and Caching issues

I should have posted this sooner, but I am noticing an alarming issue (radar://22384826) where softwareupdate is completely locking up, breaking tools in my workflow. I first started noticing this in Beta 7 and it looks like it is still happening in Beta 8.


In order to have this issue, your must have the following configuration:


Server

1. SUS Server (reposado or Apple SUS)

2. Caching Server


Client

1. El Capitan machine pointing to your SUS catalog and AssetCacheLocatorService registering a caching server.

2. Available updates


I can reliably recreate this issue by doing the following:

1 - Install Beta 7 -> Upgrade to Beta 8 (skip iTunes 12.2.2 update)

2.1 - Download a few MAS applications to invoke AssetCacheLocatorService

2.2 - If App Store has already downloaded iTunes 12.2.2, delete it from /Library/Updates/zzzz031-31870

3 - Change SUS catalog from Apple's to custom.

4 - run softwareupdate -v -d -a


What happens...


Terminal shows the following until you kill the process


softwareupdate -v -d -a

Software Update Tool

Copyright 2002-2015 Apple Inc.

Finding available software

Downloading iTunes

[50 minutes later]

[1]+ Stopped softwareupdate -v -d -a


Behind the scenes, this occurs


Client


Sep 1 07:41:03 softwareupdated[723]: softwareupdated: Catalog URL changed (from "htps://swscan.apple.com/content/catalogs/others/index-10.11seed-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz" to "htp://SUS.FQDN/content/catalogs/index.sucatalog"). Resetting state.

Sep 1 07:41:03 softwareupdated[723]: Adding client SUUpdateServiceClient pid=2388, uid=999, installAuth=NO rights=(), transactions=0 (/usr/sbin/softwareupdate)

Sep 1 07:41:03 installd[581]: PackageKit: Adding client PKInstallDaemonClient pid=723, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Sep 1 07:41:03 softwareupdated[723]: SUScan: Scan for client pid 723 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Sep 1 07:41:03 softwareupdated[723]: SoftwareUpdate: Catalog Not Modified since last scan ("2f14fc-51eaeb8324bc0")

Sep 1 07:41:03 softwareupdated[723]: SUScan: Using catalog htp://SUS.FQDN/content/catalogs/index.sucatalog

Sep 1 07:41:13 softwareupdated[723]: JS: 10.11

Sep 1 07:41:17 softwareupdated[723]: SUScan: Elapsed scan time = 13.1

Sep 1 07:41:17 softwareupdated[723]: Scan (f=1, d=0) completed

Sep 1 07:41:17 softwareupdated[723]: 3 updates found:

031-04978 | CoreLSKD Configuration Data 8

031-32566 | Gatekeeper Configuration Data 78

zzzz031-31870 | iTunes 12.2.2

Sep 1 07:41:17 softwareupdated[723]: Package Authoring: File iTunes.app/Contents/MacOS/iTunes is not in either expected pre- or post-patch state for (package: com.apple.pkg.iTunesX.12.2.2.delta)

Sep 1 07:41:17 softwareupdated[723]: Package Authoring: finalSHA1String = abbeb7d9935318fa44f6e1204bddade167668fd6, digest = d2ba3f7b7e29065669e1f38c1524d50782f3df7b, expected = cf58d83ef05c91913d0848e52dbbfacdf0200119 (package: com.apple.pkg.iTunesX.12.2.2.delta)

Sep 1 07:41:17 softwareupdated[723]: Ramped updates marked

Sep 1 07:41:18 softwareupdated[723]: SULocalProduct: zzzz031-31870 is not completely downloaded. Package with identifier com.apple.pkg.iTunesX.12.2.2.delta not found:

Sep 1 07:41:18 softwareupdated[723]: SoftwareUpdate: Added foreground transaction [0x4] for iTunesXPatch-12.2.2

Sep 1 07:41:18 softwareupdated[723]: SoftwareUpdate: starting download of zzzz031-31870 (iTunesXPatch-12.2.2)

Sep 1 07:41:18 softwareupdated[723]: SULocalProduct: zzzz031-31870 is not completely downloaded. Package with identifier com.apple.pkg.iTunesX.12.2.2.delta not found:

Sep 1 07:41:18 softwareupdated[723]: ContentLocator: Modified URL is: htp://IPOFCACHINGSERVER:CONTENTPORT/content/downloads/12/41/zzzz031-31870/abxwx2zehh8mu371hecicgx7ywh15whsy7/CoreADI.pkg?source=SUS.FQDN

Sep 1 07:41:18 softwareupdated[723]: ContentLocator: Modified URL is: htp://IPOFCACHINGSERVER:CONTENTPORT/content/downloads/12/41/zzzz031-31870/abxwx2zehh8mu371hecicgx7ywh15whsy7/MobileDevice.pkg?source=SUS.FQDN

Sep 1 07:41:18 softwareupdated[723]: ContentLocator: Modified URL is: htp://IPOFCACHINGSERVER:CONTENTPORT/content/downloads/12/41/zzzz031-31870/abxwx2zehh8mu371hecicgx7ywh15whsy7/CoreFP.pkg?source=SUS.FQDN

Sep 1 07:41:18 softwareupdated[723]: ContentLocator: Modified URL is: htp://IPOFCACHINGSERVER:CONTENTPORT/content/downloads/12/41/zzzz031-31870/abxwx2zehh8mu371hecicgx7ywh15whsy7/iTunesXDelta.pkg?source=SUS.FQDN

Sep 1 07:41:18 softwareupdated[723]: ContentLocator: Modified URL is: htp://IPOFCACHINGSERVER:CONTENTPORT/content/downloads/12/41/zzzz031-31870/abxwx2zehh8mu371hecicgx7ywh15whsy7/iTunesAccess.pkg?source=SUS.FQDN

Sep 1 07:41:18 softwareupdated[723]: Finished downloading package CoreADI.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_N2oFLQ.tmp (error (null)) from peer: IPOFCACHINGSERVER

Sep 1 07:41:18 softwareupdated[723]: zzzz031-31870: Failed post-download size check for package "CoreADI.pkg": expected 1895737, got 0

Sep 1 07:41:18 softwareupdated[723]: Finished downloading package MobileDevice.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_ccE7Zn.tmp (error (null)) from peer: IPOFCACHINGSERVER

Sep 1 07:41:18 softwareupdated[723]: zzzz031-31870: Failed post-download size check for package "MobileDevice.pkg": expected 32701833, got 0

Sep 1 07:41:18 softwareupdated[723]: Finished downloading package CoreFP.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_nqlLV2.tmp (error (null)) from peer: IPOFCACHINGSERVER

Sep 1 07:41:18 softwareupdated[723]: zzzz031-31870: Failed post-download size check for package "CoreFP.pkg": expected 26885431, got 0

Sep 1 07:41:18 softwareupdated[723]: Finished downloading package iTunesXDelta.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_zOmFt8.tmp (error (null)) from peer: IPOFCACHINGSERVER

Sep 1 07:41:18 softwareupdated[723]: zzzz031-31870: Failed post-download size check for package "iTunesXDelta.pkg": expected 70929794, got 0

Sep 1 07:41:18 softwareupdated[723]: Finished downloading package iTunesAccess.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_YGmp2I.tmp (error (null)) from peer: IPOFCACHINGSERVER

Sep 1 07:41:18 softwareupdated[723]: zzzz031-31870: Failed post-download size check for package "iTunesAccess.pkg": expected 687421, got 0

Sep 1 07:41:18 softwareupdated[723]: No more tasks - invalidating session now

Sep 1 07:41:18 softwareupdated[723]: Stopping transaction with ID [0x4]

Sep 1 07:41:18 softwareupdated[723]: SoftwareUpdate: Removed foreground transaction [0x4]


Server


2015-09-01 07:41:18.541 Request from IPOFCLIENT:CONTENTPORT [Software%20Update (unknown version) CFNetwork/720.5.7 Darwin/15.0.0 (x86_64)] for non-whitelisted URL denied


As you can see, ContentLocator takes over for softwareupdated and points it away from the SUS to the caching server. It sends the following:


ContentLocator: Modified URL is: htp://IPOFCACHINGSERVER:CONTENTPORT/content/downloads/12/41/zzzz031-31870/abxwx2zehh8mu371hecicgx7ywh15whsy7/iTunesAccess.pkg?source=SUS.FQDN


Unfortunately, the Caching server rejects the ?source=SUS.FQDN part as it is not a whitelisted URL (say for instance like swcdn.apple.com). This causes a 0Kb file to be created and softwareupdate does not know how to handle this. I have found similar behavior in Yosemite 10.10.5, but it looks like softwareupdate and ContentLocator do not work as closely together as they do in El Capitan.


Apple could fix this in a few ways:

1. Allow the admin to create an array of whitelisted FQDN's that the Caching Server can respond to.

2. Create some logic in ContentLocator that can recognize if a non-apple URL is used in the catalog and change the ?source= section to still point to Apple's whitelisted domains.

3. Create some logic in ContentLocator to stop taking over for softwareupdate when a custom catalog is set.





If you use a Caching Server and a SUS, I highly encourage you to test this behavior and send this information to your Apple SE's before El Capitan is shipped. If this is not resolved prior to GM, you may have to choose between a SUS or a Caching Server.

Replies

I was able to reproduce this in my environment. Client is running 10.11 build 15A282b, caching server is 4.1.5, and SUS is Reposado. I initially noticed the problem when munki was attempting to install Apple Software updates (Xprotect and Gatekeeper) at the loginwindow. I was able to reproduce with softwareupdate at the command line, as the process hung while trying to download the updates. Looking at the logs in caching server, I saw similar errors about bad request and the URL not being whitelisted.


Will do a few more tests and submit a radar.


--

Harry