Apple SUS internal error for product 091-00004 & 031-95676

Question

Stufe 1

15 Punkte

Apple SUS internal error for product 091-00004 & 031-95676

Hi all, hi Apple,

Did anyone with a macOS Server notice the same issue? This is currently happening at different sites with similar effects to our macOS servers with local SUS service. I forward this issue after local investigation, searching the Apple support community and unsuccessfuly waiting for a seemless resolution by a more correct official database for some days.

Apparently the official Apple SUS service (i.e. Software Update Server) introduced an error in the remote product database recently (see below). This leads to repeated failure in macOS server swupd syncs, loads of error log lines and some waste of bandwidth.

IMHO this needs action by Apple to adminstratively update and correct the official Apple SUS service database.

relevant product codes:

091-00004
031-95676

(this may differ between local servers)

As a side effect the local SUS service daemon repeatedly re-downloads the complete (!!) SUS database from the remote Apple SUS service database. This results in waste of bandwidth however only once a day during night. Please notice that all other products are downloaded correctly before and after the failed two products in each run.

Investigating the database files (see B below) shows incorrect file names in the copy downloaded from the remote source.

(A) excerpt of error log:

...

Jul 17 03:00:00 swupd_syncd[89383] <Info>: ========== Sync Started ==========

Jul 17 03:00:00 swupd_syncd[89383] <Info>: Checking service data location: /Library/Server/Software Update/Data/html

Jul 17 03:00:00 swupd_syncd[89383] <Info>: Retrieving catalog list

Jul 17 03:00:00 swupd_syncd[89383] <Info>: Retrieving deprecated updates list

2017-07-17 03:00:00.352 swupd_syncd[89383:5064410] NetworkStorageDB:_openDBReadConnections: failed to open read connection to DB @ /var/empty/Library/Caches/swupd_syncd/Cache.db. Error=14. Cause=unable to open database file

2017-07-17 03:00:00.352 swupd_syncd[89383:5064410] CacheRead: unable to open cache files in /var/empty/Library/Caches/swupd_syncd

2017-07-17 03:00:00.352 swupd_syncd[89383:5064410] Failed to obtain sandbox extension for path=/var/empty/Library/Caches/swupd_syncd. Errno:2

Jul 17 03:00:00 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.suc atalog

Jul 17 03:00:02 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:00:04 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:00:05 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:00:06 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:00:06 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:00:07 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-leopard-snowleopard.merged-1.sucatalog

Jul 17 03:00:08 swupd_syncd[89383] <Info>: Updating local catalog: index-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.suc atalog

Jul 17 03:01:40 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:01:40 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:01:40 swupd_syncd[89383] <Info>: Previously copied product 091-00008 missing from local storage. This product will be re-download.

Jul 17 03:01:40 swupd_syncd[89383] <Info>: Previously copied product 091-00006 missing from local storage. This product will be re-download.

Jul 17 03:01:41 swupd_syncd[89383] <Info>: Previously copied product 091-21957 missing from local storage. This product will be re-download.

Jul 17 03:01:41 swupd_syncd[89383] <Info>: Previously copied product 091-21439 missing from local storage. This product will be re-download.

Jul 17 03:01:41 swupd_syncd[89383] <Info>: Previously copied product 091-21944 missing from local storage. This product will be re-download.

Jul 17 03:01:41 swupd_syncd[89383] <Info>: Previously copied product 091-00010 missing from local storage. This product will be re-download.

Jul 17 03:01:41 swupd_syncd[89383] <Info>: Previously copied product 091-21475 missing from local storage. This product will be re-download.

Jul 17 03:01:41 swupd_syncd[89383] <Info>: Previously copied product 091-21496 missing from local storage. This product will be re-download.

Jul 17 03:01:42 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:01:42 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:01:42 swupd_syncd[89383] <Info>: Updating local catalog: index-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:03:21 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:03:21 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:03:21 swupd_syncd[89383] <Info>: Previously copied product 091-00008 missing from local storage. This product will be re-download.

Jul 17 03:03:21 swupd_syncd[89383] <Info>: Previously copied product 091-00006 missing from local storage. This product will be re-download.

Jul 17 03:03:21 swupd_syncd[89383] <Info>: Previously copied product 091-21944 missing from local storage. This product will be re-download.

Jul 17 03:03:21 swupd_syncd[89383] <Info>: Previously copied product 091-00010 missing from local storage. This product will be re-download.

Jul 17 03:03:21 swupd_syncd[89383] <Info>: Previously copied product 091-21496 missing from local storage. This product will be re-download.

Jul 17 03:03:21 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:03:21 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:03:22 swupd_syncd[89383] <Info>: Updating local catalog: index-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:05:28 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:05:28 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:05:28 swupd_syncd[89383] <Info>: Previously copied product 091-21944 missing from local storage. This product will be re-download.

Jul 17 03:05:28 swupd_syncd[89383] <Info>: Previously copied product 091-00008 missing from local storage. This product will be re-download.

Jul 17 03:05:28 swupd_syncd[89383] <Info>: Previously copied product 091-00010 missing from local storage. This product will be re-download.

Jul 17 03:05:29 swupd_syncd[89383] <Info>: Previously copied product 091-00006 missing from local storage. This product will be re-download.

Jul 17 03:05:29 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:05:29 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:05:29 swupd_syncd[89383] <Info>: Updating local catalog: index-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:06:53 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:06:53 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:06:53 swupd_syncd[89383] <Info>: Previously copied product 091-00008 missing from local storage. This product will be re-download.

Jul 17 03:06:53 swupd_syncd[89383] <Info>: Previously copied product 091-00006 missing from local storage. This product will be re-download.

Jul 17 03:06:53 swupd_syncd[89383] <Info>: Previously copied product 091-21944 missing from local storage. This product will be re-download.

Jul 17 03:06:53 swupd_syncd[89383] <Info>: Previously copied product 091-00010 missing from local storage. This product will be re-download.

Jul 17 03:06:53 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:06:53 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:06:53 swupd_syncd[89383] <Info>: Updating local catalog: index-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:08:09 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:08:09 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:08:09 swupd_syncd[89383] <Info>: Previously copied product 091-00008 missing from local storage. This product will be re-download.

Jul 17 03:08:09 swupd_syncd[89383] <Info>: Previously copied product 091-00006 missing from local storage. This product will be re-download.

Jul 17 03:08:09 swupd_syncd[89383] <Info>: Previously copied product 091-21944 missing from local storage. This product will be re-download.

Jul 17 03:08:09 swupd_syncd[89383] <Info>: Previously copied product 091-00010 missing from local storage. This product will be re-download.

Jul 17 03:08:09 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:08:09 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:08:09 swupd_syncd[89383] <Info>: Updating local catalog: index-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:09:39 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:09:39 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:09:39 swupd_syncd[89383] <Info>: Previously copied product 091-00008 missing from local storage. This product will be re-download.

Jul 17 03:09:39 swupd_syncd[89383] <Info>: Previously copied product 091-00006 missing from local storage. This product will be re-download.

Jul 17 03:09:39 swupd_syncd[89383] <Info>: Previously copied product 091-00010 missing from local storage. This product will be re-download.

Jul 17 03:09:39 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:09:40 swupd_syncd[89383] <Info>: Updating local catalog: index-leopard-snowleopard.merged-1.sucatalog

Jul 17 03:10:22 swupd_syncd[89383] <Info>: * Auto-copy (ALL) option is ON. Applying option to eligible products.

Jul 17 03:10:22 swupd_syncd[89383] <Info>: * Auto-enable option is ON. Applying option to eligible products.

Jul 17 03:10:23 swupd_syncd[89383] <Info>: Updating product updates information

Jul 17 03:10:24 swupd_syncd[89383] <Info>: Starting product update downloads

...

Jul 17 03:23:06 swupd_syncd[89383] <Info>: Downloading: Canon Inkjet Printer Software Update 3.4 (ID: 091-00004, posted: 2017-07-06 15:56:15 +0000)

...

Jul 17 03:24:18 swupd_syncd[89383] <Error>: *** Product file URL contains possible security violation.

Jul 17 03:24:18 swupd_syncd[89383] <Error>: *** Product ID: "091-00004"; file URL: "(null)"

Jul 17 03:24:18 swupd_syncd[89383] <Error>: *** Local path: /Library/Server/Software Update/Data/html

Jul 17 03:24:18 swupd_syncd[89383] <Error>: *** Reason: file URL contains invalid scheme (should be "http")

Jul 17 03:24:18 swupd_syncd[89383] <Error>: *** The suspect product file will not be downloaded.

...

Jul 17 03:21:59 swupd_syncd[89383] <Info>: Downloading: Brother Printer Software Update 4.1.1 (ID: 031-95676, posted: 2017-07-06 15:56:15 +0000)

Jul 17 03:22:00 swupd_syncd[89383] <Error>: *** Product file URL contains possible security violation.

Jul 17 03:22:00 swupd_syncd[89383] <Error>: *** Product ID: "031-95676"; file URL: "(null)"

Jul 17 03:22:00 swupd_syncd[89383] <Error>: *** Local path: (null)

Jul 17 03:22:00 swupd_syncd[89383] <Error>: *** Reason: file URL contains invalid scheme (should be "http")

Jul 17 03:22:00 swupd_syncd[89383] <Error>: *** The suspect product file will not be downloaded.

...

Jul 17 03:24:20 swupd_syncd[89383] <Info>: Finished downloading product: 091-00004

Jul 17 03:24:20 swupd_syncd[89383] <Info>: Downloading: Lexmark Printer Software Update 3.2 (ID: 091-00010, posted: 2017-07-06 15:56:14 +0000)

Jul 17 03:25:21 swupd_syncd[89383] <Info>: Finished downloading product: 091-00010

Jul 17 03:25:21 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:25:21 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:25:21 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 091-00004.

Jul 17 03:25:22 swupd_syncd[89383] <Error>: *** Internal error creating cache data for product 031-95676.

Jul 17 03:25:23 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.suc atalog

Jul 17 03:25:26 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:25:28 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:25:30 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:25:31 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:25:32 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-lion-snowleopard-leopard.merged-1.sucatalog

Jul 17 03:25:33 swupd_syncd[89383] <Info>: Retrieving remote catalog (SECURE): index-leopard-snowleopard.merged-1.sucatalog

Jul 17 03:25:33 swupd_syncd[89383] <Info>: Sync Complete

NB: The two failed downloads result in almost a hundred repeated error messages for each run.

(B) investigating the local database:

cd "/Library/Server/Software Update/Data/html/content/catalogs/others"

ls -l

-rw-r--r-- 1 _softwareupdate _softwareupdate 4370539 17 Jul 03:25 index-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 5743063 15 Jul 03:36 index-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.apple

-rw-r--r-- 1 _softwareupdate _softwareupdate 4282762 17 Jul 03:25 index-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 5628512 15 Jul 03:35 index-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog .apple

-rw-r--r-- 1 _softwareupdate _softwareupdate 4264087 17 Jul 03:25 index-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.suc atalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 5605137 15 Jul 20:12 index-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.suc atalog.apple

-rw-r--r-- 1 _softwareupdate _softwareupdate 1396984 17 Jul 03:25 index-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 1840568 13 Jul 21:59 index-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.apple

-rw-r--r-- 1 _softwareupdate _softwareupdate 1642670 17 Jul 03:25 index-leopard-snowleopard.merged-1.sucatalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 1994928 13 Jul 19:48 index-leopard-snowleopard.merged-1.sucatalog.apple

-rw-r--r-- 1 _softwareupdate _softwareupdate 2169218 17 Jul 03:25 index-lion-snowleopard-leopard.merged-1.sucatalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 2682393 13 Jul 19:48 index-lion-snowleopard-leopard.merged-1.sucatalog.apple

-rw-r--r-- 1 _softwareupdate _softwareupdate 1672483 17 Jul 03:25 index-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog

-rw-r--r-- 1 _softwareupdate _softwareupdate 2147197 13 Jul 21:59 index-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.apple

Apparently the files ".sucatalog.apple" are the mandatory catalogs copied from the official remote source. Investigating one or all of these shows several incorrect entries in the data arrays of the respective product keys.

vi index-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.suc atalog.apple

<?xml version="1.0"?>

<!DOCTYPE plist PUBLIC "-//Apple Computer//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">

<dict>

<key>CatalogVersion</key>

<key>ApplePostURL</key>

<string>http://swpost.apple.com/stats</string>

<key>IndexDate</key>

<key>Products</key>

...

<dict>

<key>ServerMetadataURL</key>

<string>http://swcdn.apple.com/content/downloads/52/10/091-00004/2qabotf6wff6byv5rhz7ktn x7dfwlbrvrq/Canon_PrinterSupport.smd</string>

<key>Packages</key>

<array>

<dict>

<key>Digest</key>

<key>MetadataURL</key>

<string>https://swdist.apple.com/content/downloads/52/10/091-00004/2qabotf6wff6byv5rhz7k tnx7dfwlbrvrq/Canon_SharedLibraries14.pkm</string>

<string>http://swcdn.apple.com/content/downloads/52/10/091-00004/2qabotf6wff6byv5rhz7ktn x7dfwlbrvrq/Canon_SharedLibraries14.pkg</string>

</dict>

...

<dict>

<string>http://swcdn.apple.com/content/downloads/52/10/091-00004/2qabotf6wff6byv5rhz7ktn x7dfwlbrvrq/Canon_ICAMFP14Fall 2.pkg</string>

</dict>

<dict>

<string>http://swcdn.apple.com/content/downloads/52/10/091-00004/2qabotf6wff6byv5rhz7ktn x7dfwlbrvrq/Canon_InkjetProSeries11xx2 2.pkg</string>

</dict>

...

<dict>

<key>ServerMetadataURL</key>

<string>http://swcdn.apple.com/content/downloads/01/48/031-95676/ok4gt5zyf2phe0fpkq9w2a2 j0eptqkjpfp/Brother_PrinterSupport.smd</string>

<key>Packages</key>

<array>

<dict>

<key>Digest</key>

<key>MetadataURL</key>

<string>https://swdist.apple.com/content/downloads/01/48/031-95676/ok4gt5zyf2phe0fpkq9w2 a2j0eptqkjpfp/Brother_Utility.pkm</string>

<string>http://swcdn.apple.com/content/downloads/01/48/031-95676/ok4gt5zyf2phe0fpkq9w2a2 j0eptqkjpfp/Brother_Utility.pkg</string>

</dict>

<dict>

<string>http://swcdn.apple.com/content/downloads/01/48/031-95676/ok4gt5zyf2phe0fpkq9w2a2 j0eptqkjpfp/Brother_ICA 2.pkg</string>

</dict>

...

Please notice the exemplary incorrect URLs and the presumably disallowed linespace in each file name:

http://swcdn.apple.com/content/downloads/52/10/091-00004/2qabotf6wff6byv5rhz7ktn x7dfwlbrvrq/Canon_InkjetProSeries11xx2 2.pkg
http://swcdn.apple.com/content/downloads/01/48/031-95676/ok4gt5zyf2phe0fpkq9w2a2 j0eptqkjpfp/Brother_ICA 2.pkg

There are several different incorrect (and correct) URLs more for each product as these hold several file packages.

IMHO this looks like a typical (remote) copy problem and the standard behaviour of HFS+ to add a space and an index number to a file name after a collision of a copy same operation. I tried several steps including deleting all local catalog files and always a fresh copy from the remote source gave a new .sucatalog.apple file with incorrect URLs to the products identified. This holds for most if not all different flavours of Mac OS X / macOS release catalogs.

Comprisingly this leads to my a.m. assumption that Apple needs to correct their remote official database administratevely.

However, my assumptions may be incorrect and I would appreciate any advice.

null-OTHER, macOS Sierra (10.12.5), macOS Server 5.3.1

Gepostet am 17. Juli 2017 13:01

Antworten