Munki sometimes not installing Apple updates on logout

[Michal Moravec]

Hello,

there was a user with 10.11.6 and munkitools 2.8.2 installed.

He says to me: "I atempted to install Safari 10.0.1 through Managed Software Center (restart required) multiple times but it's still present in list of updates.

So I investigate. There are 3 updates in MSC.app. Google Chrome, latest El Cap security update and latest Safari. I hit update and go on with logoutinstall.

After logout I command + L to view log. Chrome installs normally but Apple updates fail quickly. Restart.

Oct 31 2016 10:47:20 +0100 WARNING: Apple update Safari, 031-81873 may have failed to install. No record of success or failure.

Oct 31 2016 10:47:20 +0100 WARNING: Apple update Security Update 2016-002, 031-75995 may have failed to install. No record of success or failure.

After boot I logged in as local admin, backed up /Library/Managed\ Installs directory for later troubleshooting (part of it in zipped attachment) and run following in Termainal

sudo managedsoftwareupdate --applesuspkgsonly
sudo managedsoftwareupdate --installonly

applesuspkgsonly downloaded both Apple updates. installonly installed updates without any problem.

This problem happend to one or two users before (-> rare and random).

Log files and swupd directory are in ziped attachment.

How should I debug (gather more info) next time I see this problem?

[Michal Moravec]

I discovered second user with this problem.

Both of them are in Reposado testing branch.

–> they had access to this update before I created pkginfo file in Munki with force_install_after _date for these two Apple updates.

[Michal Moravec]

I found AppleUpdates.plist file in Managed Installs in case of second user. It wasn't there in case of first user.

[gregn...@mac.com]

/usr/sbin/softwareupdate itself logs to /var/log/install.log, so that's where I'd look for additional clues.

-Greg

[Michal Moravec]

# Munki log (case 1)

Oct 31 2016 11:58:08 +0100 WARNING: Apple update Safari, 031-81873 may have failed to install. No record of success or failure.

Oct 31 2016 11:58:08 +0100 WARNING: Apple update Security Update 2016-002, 031-75995 may have failed to install. No record of success or failure.

# install.log (case 1)

Oct 31 11:58:06 macmac softwareupdated[3909]: softwareupdated: Starting with build 10.11.6 (15G1004)

Oct 31 11:58:06 macmac softwareupdated[3909]: SoftwareUpdate: 031-81873 (Safari10.0.1ElCapitan-10.0.1): install-later not supported for restart-required update (options={

   customize = never;

   hostArchitectures = i386;

})

Oct 31 11:58:07 macmac softwareupdated[3909]: /Library/Bundles does not exist - watching for directory creation

Oct 31 11:58:07 macmac softwareupdated[3909]: BackgroundActivity: Activity check-in with Interval 21600 

Oct 31 11:58:07 macmac softwareupdated[3909]: Adding client SUUpdateServiceClient pid=3908, uid=0, installAuth=NO rights=(), transactions=0 (/usr/sbin/softwareupdate)

Oct 31 11:58:07 macmac installd[3408]: PackageKit: Adding client PKInstallDaemonClient pid=3909, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Oct 31 11:58:07 macmac softwareupdated[3909]: Cannot find local product 031-75995 in index file

Oct 31 11:58:07 macmac softwareupdated[3909]: Cannot find local product 031-81873 in index file

Oct 31 11:58:07 macmac installd[3408]: PackageKit: Adding client PKInstallDaemonClient pid=3909, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Oct 31 11:58:07 macmac installd[3408]: PackageKit: Removing client PKInstallDaemonClient pid=3909, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Oct 31 11:58:07 --- last message repeated 1 time ---

Oct 31 11:58:07 macmac softwareupdated[3909]: SUUpdateSession startUpdateForProducts:<SUProduct: 031-75995>, <SUProduct: 031-81873> inForeground: YES staged: NO

Oct 31 11:58:07 macmac softwareupdated[3909]: SoftwareUpdate: Added foreground transaction [0x1] for Security Update 2016-002-10.11.6, Safari10.0.1ElCapitan-10.0.1

Oct 31 11:58:07 macmac softwareupdated[3909]: Cannot find local product 031-75995 in index file

Oct 31 11:58:07 macmac softwareupdated[3909]: SoftwareUpdate: Invalid or incomplete local product 031-75995

Oct 31 11:58:07 macmac softwareupdated[3909]: Removing local product after found to be incomplete

Oct 31 11:58:07 macmac softwareupdated[3909]: Removed local product for 031-75995 (1)

Oct 31 11:58:07 macmac softwareupdated[3909]: Cannot find local product 031-81873 in index file

Oct 31 11:58:07 macmac softwareupdated[3909]: SoftwareUpdate: Invalid or incomplete local product 031-81873

Oct 31 11:58:07 macmac softwareupdated[3909]: Removing local product after found to be incomplete

Oct 31 11:58:07 macmac softwareupdated[3909]: Removed local product for 031-81873 (1)

Oct 31 11:58:07 macmac softwareupdated[3909]: Stopping transaction with ID [0x1]

Oct 31 11:58:07 macmac softwareupdated[3909]: SoftwareUpdate: Removed foreground transaction [0x1]

Oct 31 11:58:07 macmac softwareupdated[3909]: Running session-idle tasks.

Oct 31 11:58:07 macmac softwareupdated[3909]: Checking for inapplicable local products remaining on disk for cleanup

Oct 31 11:58:07 macmac softwareupdated[3909]: Removing client SUUpdateServiceClient pid=3908, uid=0, installAuth=YES rights=(system.install.apple-software, system.install.apple-software.standard-user, system.install.software, com.apple.SoftwareUpdate.modify-settings), transactions=0 (/usr/sbin/softwareupdate)

Oct 31 11:58:36 macmac loginwindow[96]: IASGetCurrentInstallPhaseList: no install phase array set

Oct 31 11:58:36 macmac loginwindow[96]: IASGetCurrentInstallPhase: no install phase set

Oct 31 11:58:42 macmac softwareupdate_firstrun_tasks[92]: Host reposado.company.com isReachable = YES

Oct 31 11:59:15 macmac softwareupdate_firstrun_tasks[92]: BuildTagCache: Building tag cache if necessary using catalog host reposado.company.com

Oct 31 11:59:15 macmac softwareupdated[236]: softwareupdated: Starting with build 10.11.6 (15G1004)

Oct 31 11:59:16 macmac softwareupdated[236]: SoftwareUpdate: 031-81873 (Safari10.0.1ElCapitan-10.0.1): install-later not supported for restart-required update (options={

   customize = never;

   hostArchitectures = i386;

})

Oct 31 11:59:16 macmac softwareupdated[236]: /Library/Bundles does not exist - watching for directory creation

Oct 31 11:59:16 macmac softwareupdated[236]: BackgroundActivity: Activity check-in with Interval 21600 

Oct 31 11:59:16 macmac softwareupdated[236]: Adding client SUUpdateServiceClient pid=92, uid=200, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_firstrun_tasks)

Oct 31 11:59:16 macmac softwareupdated[236]: BuildTagCache:  Cache is current

Oct 31 11:59:16 macmac softwareupdate_firstrun_tasks[92]: BuildTagCache:  Finished

Oct 31 11:59:16 macmac softwareupdated[236]: Removing client SUUpdateServiceClient pid=92, uid=200, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_firstrun_tasks)

# Munki log (case 2)

Oct 28 2016 11:09:05 +0200 WARNING: Apple update Safari, 031-81873 may have failed to install. No record of success or failure.

Oct 28 2016 11:09:05 +0200 WARNING: Apple update Safari, 031-78814 may have failed to install. No record of success or failure.

Oct 28 2016 11:09:05 +0200 WARNING: Apple update Security Update 2016-002, 031-75995 may have failed to install. No record of success or failure.

# install.log (case 2)

Oct 28 11:09:05 macmac softwareupdated[63739]: Adding client SUUpdateServiceClient pid=67230, uid=0, installAuth=NO rights=(), transactions=0 (/usr/sbin/softwareupdate)

Oct 28 11:09:05 macmac installd[63548]: PackageKit: Adding client PKInstallDaemonClient pid=63739, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-75995 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-78814 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-81873 in index file

Oct 28 11:09:05 macmac installd[63548]: PackageKit: Adding client PKInstallDaemonClient pid=63739, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Oct 28 11:09:05 macmac installd[63548]: PackageKit: Removing client PKInstallDaemonClient pid=63739, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Oct 28 11:09:05 --- last message repeated 2 times ---

Oct 28 11:09:05 macmac softwareupdated[63739]: SUUpdateSession startUpdateForProducts:<SUProduct: 031-75995>, <SUProduct: 031-78814>, <SUProduct: 031-81873> inForeground: YES staged: NO

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Added foreground transaction [0x2] for Security Update 2016-002-10.11.6, Safari10.0ElCapitan-10.0, Safari10.0.1ElCapitan-10.0.1

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-75995 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Invalid or incomplete local product 031-75995

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing local product after found to be incomplete

Oct 28 11:09:05 macmac softwareupdated[63739]: Removed local product for 031-75995 (1)

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-78814 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Invalid or incomplete local product 031-78814

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing local product after found to be incomplete

Oct 28 11:09:05 macmac softwareupdated[63739]: Removed local product for 031-78814 (1)

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-81873 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Invalid or incomplete local product 031-81873

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing local product after found to be incomplete

Oct 28 11:09:05 macmac softwareupdated[63739]: Removed local product for 031-81873 (1)

Oct 28 11:09:05 macmac softwareupdated[63739]: Stopping transaction with ID [0x2]

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Removed foreground transaction [0x2]

Oct 28 11:09:05 macmac softwareupdated[63739]: Running session-idle tasks.

Oct 28 11:09:05 macmac softwareupdated[63739]: Checking for inapplicable local products remaining on disk for cleanup

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing client SUUpdateServiceClient pid=67230, uid=0, installAuth=YES rights=(system.install.apple-software, system.install.apple-software.standard-user, system.install.software, com.apple.SoftwareUpdate.modify-settings), transactions=0 (/usr/sbin/softwareupdate)

Oct 28 11:09:45 macmac loginwindow[95]: IASGetCurrentInstallPhaseList: no install phase array set

Oct 28 11:09:45 macmac loginwindow[95]: IASGetCurrentInstallPhase: no install phase set

Oct 28 11:10:02 macmac softwareupdate_firstrun_tasks[91]: Host reposado.company.com isReachable = YES

Oct 28 11:10:35 macmac softwareupdate_firstrun_tasks[91]: BuildTagCache: Building tag cache if necessary using catalog host reposado.company.com

Oct 28 11:10:35 macmac softwareupdated[239]: softwareupdated: Starting with build 10.11.6 (15G1004)

Oct 28 11:10:35 macmac softwareupdated[239]: SoftwareUpdate: 031-78814 (Safari10.0ElCapitan-10.0): install-later not supported for restart-required update (options={

   customize = never;

   hostArchitectures = i386;

})

Oct 28 11:10:35 macmac softwareupdated[239]: SoftwareUpdate: 031-81873 (Safari10.0.1ElCapitan-10.0.1): install-later not supported for restart-required update (options={

   customize = never;

   hostArchitectures = i386;

})

Oct 28 11:10:35 macmac softwareupdated[239]: /Library/Bundles does not exist - watching for directory creation

Oct 28 11:10:35 macmac softwareupdated[239]: BackgroundActivity: Activity check-in with Interval 21600 

Oct 28 11:10:35 macmac softwareupdated[239]: Adding client SUUpdateServiceClient pid=91, uid=200, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_firstrun_tasks)

Oct 28 11:10:35 macmac softwareupdated[239]: BuildTagCache:  Cache is current

Oct 28 11:10:35 macmac softwareupdate_firstrun_tasks[91]: BuildTagCache:  Finished

Oct 28 11:10:35 macmac softwareupdated[239]: Removing client SUUpdateServiceClient pid=91, uid=200, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_firstrun_tasks)

[Gregory Neagle]

There's your smoking gun:

[Michal Moravec]

Removing local product after found to be incomplete

Could this be update .pkg file not completely downloaded (say timeout happening for example) by softwareupdate but Munki thinks it is downloaded?

[Paul Hildahl]

I'm having the same issues (10.11.6, Munki 2.8.2.2855), most commonly with the new Security Update 2016-002 (031-75995) and Safari 10.0.1 (031-81873) being served by reposado. To work around the issue with Security Update 2016-002, I manually added the .pkg from Apple's support download http://support.apple.com/downloads/DL1891/en_US/secupd2016-002elcapitan.dmg

[Michal Moravec]

I've encoutered the same problem in different company with different Reposado server (updates are replicated).

Safari 10.0.1 and latest ElCap security update (2016-002 10.11.6).

This server is connected to LAN (my first case was Reposado server accessed over WAN link)

I'm sorry I can't spend more time on this troubleshooting :-(

install.log attached.

[Mike Solin]

Do you have a caching server enabled on the same network?

Mike

--

mi...@mikesolin.com / @flammable

http://mikesolin.com

--
Find related discussion groups here:
https://github.com/munki/munki/wiki/Discussion-Group
---
You received this message because you are subscribed to the Google Groups "munki-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+unsubscribe@googlegroups.com.
To post to this group, send email to munk...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Michal Moravec]

On Wednesday, November 30, 2016 at 6:40:51 PM UTC+1, Mike Solin wrote:

Do you have a caching server enabled on the same network?

Nope.

[Michal Moravec]

This problem keeps coming back.

Now with latest El Capitan security update: 031-96040

I spent hour remotely troublshooting one particular case:

- 031-96040 is correctly cached in /Library/Updates/ 031-96040 (sha1 hashes check)

- Array /Library/Updates/index.plist in ProductPaths is empty. I checked one unmanaged Mac with same pending udpate and 031-96040 was in ProductPaths array. 

- Mac does not have enought space to install Apple udpate.

softwareupdate -i -a won't let me install udpate because of it.

managesfotwareupdate --instalonly ends with 

Apple update ... may have failed to install. No record of success or failure.

/var/log/install.log says 

Cannot find local product 031-75995 in index file

When I made enough space for update to be installed subsequent managesfotwareupdate --instalonly ended with

Apple update ... may have failed to install. No record of success or failure.

Cannot find local product 031-75995 in index file

but this time /Library/Updates/ 031-96040 and /Library/Updates/index.plist were deleted.

Next run:

managesfotwareupdate
managesfotwareupdate --instalonly

successfully installed the El Cap security udpate.

Anyone know for sure that index file mentionioned in install.log is 100% sure  /Library/Updates/index.plist?

[sondjata]

Been seeing the same problem but available space was not the issue.

[Michal Moravec]

Available space is related only to this single troubleshooting case.

I see this in Munki Report with other Macs.

f.e. There is a MBA with 20 GB available space where 10.12.2 failed to update to 10.12.4  (so it is not limited to El Captian :-()

[Michal Moravec]

So there was a Munki deadline for Apple updates yesterday.

I was monitoring Munki Report and I see consistent behavior on almost all Macs:

- Apple updates (mostly 10.12.4 and latest El Cap security update) were cached in /Library/Updates for 3+ weeks

- On first forced logout install Apple updates failed to install.

- On second forced logout install Apple updates were installed correctly.

There is a discussion on Macsysadmin slack where others seen this as well.

- Apple updates are cached for a longer period of time

- softwareupdate fails to install them with `Cannot find local product XXX in index file`

- on next softwareupdate run cache is nuked, updates are redownloaded and installation succedes.

- this issue does not happen if update is initiated through MAS app.

I will try to dig into this a bit more. Currently it looks like a problem with softwareupdate tool.

[Mike Solin]

If the download becomes invalidated after a certain period of time, I wonder if a possible solution would be to nuke the cache periodically and redownload.

On the machines that have this problem, is there a high amount of uptime?  Does this persist across reboots?

Mike

-- 

mi...@mikesolin.com / @flammable
http://mikesolin.com

--
Find related discussion groups here:
https://github.com/munki/munki/wiki/Discussion-Group
---
You received this message because you are subscribed to the Google Groups "munki-dev" group.

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+...@googlegroups.com.

[Steve Maser]

So we were hoping to swing back to this.   Today is the day we are requiring people to install 10.12.5 and the security updates for 10.10, 10.11.   But we are seeing  *a few* machines (a small percentage of the vast majority) having this same issue -- where the updates appear to not be fully downloaded and *unless we release some other unnecessary apple update -- like an MRT update or a "SafeView" update* -- there is never another munki run that is checking for a re-download of what seems to be "partial" downloads of these updates.

We end up issuing workarounds with "softwareupdate -l -a" -- but that's a brute-force fix that requires help from others.

Is there any possible thought that Munki 3 is going to work differently in this scenario?   We just don't know *why* the updates are only getting partially downloaded.

But, yeah, this likely affects machines that rarely reboot as far as we can tell...

[Gregory Neagle]

On Jun 2, 2017, at 1:55 PM, Steve Maser <ma...@umich.edu> wrote:

So we were hoping to swing back to this.   Today is the day we are requiring people to install 10.12.5 and the security updates for 10.10, 10.11.   But we are seeing  *a few* machines (a small percentage of the vast majority) having this same issue -- where the updates appear to not be fully downloaded and *unless we release some other unnecessary apple update -- like an MRT update or a "SafeView" update* -- there is never another munki run that is checking for a re-download of what seems to be "partial" downloads of these updates.

We end up issuing workarounds with "softwareupdate -l -a" -- but that's a brute-force fix that requires help from others.

Is there any possible thought that Munki 3 is going to work differently in this scenario?  

No -- there's been almost no change in how Munki 3 handles Apple updates via /usr/sbin/softwareupdate.

We just don't know *why* the updates are only getting partially downloaded.

And as long as we don't know why `softwareupdate -da` does this sometimes, and/or what to do to prevent it/detect it/remediate it, we'll never be able to attempt to address it.

But, yeah, this likely affects machines that rarely reboot as far as we can tell...

On Monday, October 31, 2016 at 2:44:11 PM UTC-4, gregn...@mac.com wrote:

There's your smoking gun:

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Added foreground transaction [0x2] for Security Update 2016-002-10.11.6, Safari10.0ElCapitan-10.0, Safari10.0.1ElCapitan-10.0.1

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-75995 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Invalid or incomplete local product 031-75995

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing local product after found to be incomplete

Oct 28 11:09:05 macmac softwareupdated[63739]: Removed local product for 031-75995 (1)

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-78814 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Invalid or incomplete local product 031-78814

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing local product after found to be incomplete

Oct 28 11:09:05 macmac softwareupdated[63739]: Removed local product for 031-78814 (1)

Oct 28 11:09:05 macmac softwareupdated[63739]: Cannot find local product 031-81873 in index file

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Invalid or incomplete local product 031-81873

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing local product after found to be incomplete

Oct 28 11:09:05 macmac softwareupdated[63739]: Removed local product for 031-81873 (1)

Oct 28 11:09:05 macmac softwareupdated[63739]: Stopping transaction with ID [0x2]

Oct 28 11:09:05 macmac softwareupdated[63739]: SoftwareUpdate: Removed foreground transaction [0x2]

Oct 28 11:09:05 macmac softwareupdated[63739]: Running session-idle tasks.

Oct 28 11:09:05 macmac softwareupdated[63739]: Checking for inapplicable local products remaining on disk for cleanup

Oct 28 11:09:05 macmac softwareupdated[63739]: Removing client SUUpdateServiceClient pid=67230, uid=0, installAuth=YES rights=(system.install.apple-software, system.install.apple-software.standard-user, system.install.software, com.apple.SoftwareUpdate.modify-settings), transactions=0 (/usr/sbin/softwareupdate)

[Robinson Nuñez]

So 10.12.6 update seems to be installing at first attempt in all clients.

[Gregory Neagle]

That's good -- but ironic, since it seemed to fail on the first attempt for me...

Ah, softwareupdate...

-Greg

[Steve Maser]

So I wanted to swing back to this thread to pass on something that we discovered here (which I reported to Apple, but am not sure if there's anything Munki-related to do to mitigate this issue...)

Today is our day when we have the 10.11/10.12 security updates (and 10.13.1) force install on users if they haven't installed them manually yet via MSC.

Yet -- as with any set of Apple updates -- we have the set of users who "FAILED" when attempting to install these updates.   And -- at least in the unit I manage -- they seemed to be the same users.   "softwareupdate -i -a" always worked, though when it came down to it.

After digging around, what we found was that for these users -- and a number of other users -- their /Library/Updates folders were full of cruft.

Here's an example of one of my most problematic users who never installs updates until forced:

drwxr-xr-x  14 root  wheel    476 Nov 17 10:03 .

drwxr-xr-x+ 67 root  wheel   2278 Jun  6 20:25 ..

drwxr-xr-x   8 root  wheel    272 May 19  2017 031-99462

drwxr-xr-x   5 root  wheel    170 Mar  2  2017 031-99536

drwxr-xr-x   5 root  wheel    170 Oct 19 15:57 091-00938

drwxr-xr-x   5 root  wheel    170 Mar 23  2017 091-03215

drwxr-xr-x   8 root  wheel    272 Mar 30  2017 091-03392

drwxr-xr-x   5 root  wheel    170 Aug 10 20:58 091-16478

drwxr-xr-x   5 root  wheel    170 Oct 19 15:57 091-30878

-rw-r--r--@  1 root  wheel    181 Nov 17 10:03 PPDVersions.plist

-rw-r--r--@  1 root  wheel  35964 Nov 17 10:03 ProductMetadata.plist

drwxr-xr-x   9 root  wheel    306 Oct 19 15:57 zzzz031-97712

drwxr-xr-x   9 root  wheel    306 Mar 23  2017 zzzz091-03400

drwxr-xr-x   9 root  wheel    306 May 18  2017 zzzz091-14261

I had a couple of other users with folders not this bad, but who had some "old" updates:

drwxr-xr-x  11 root  wheel    374 Nov 17 13:59 .

drwxr-xr-x+ 69 root  wheel   2346 May 27 02:47 ..

drwxr-xr-x   5 root  wheel    170 Nov  1 09:33 091-00938

drwxr-xr-x   5 root  wheel    170 Nov  1 09:33 091-30878

drwxr-xr-x   5 root  wheel    170 Nov 17 14:00 091-32581

drwxr-xr-x   8 root  wheel    272 Nov 17 14:00 091-41055

-rw-r--r--@  1 root  wheel    181 Nov 17 13:59 PPDVersions.plist

-rw-r--r--@  1 root  wheel  37042 Nov 17 13:59 ProductMetadata.plist

-rw-r--r--   1 root  wheel    394 Nov 17 13:59 index.plist

drwxr-xr-x   9 root  wheel    306 Nov  1 09:33 zzzz031-97712

drwxr-xr-x   9 root  wheel    306 Nov 17 14:00 zzzz091-30741

on this computer, the user had tried (and failed) 3 times to install the current "Nov 17" packages we have available (Safari 11.0.1, iTunes 12.7.1 and the 10.12 security update)   User tried 3 times since we released them and they kept failing

I deleted the "Nov 1" folders -- and had the user run updates -- and it worked.

Another user looked like this:

drwxr-xr-x  10 root  wheel    340 Nov 17 13:47 .
drwxr-xr-x+ 67 root  wheel   2278 May 26 09:59 ..
drwxr-xr-x   5 root  wheel    170 Oct 12 14:11 091-00938
drwxr-xr-x   5 root  wheel    170 Oct 12 14:11 091-30878
drwxr-xr-x   5 root  wheel    170 Nov 17 13:47 091-32581
drwxr-xr-x   8 root  wheel    272 Nov 17 13:47 091-41055
-rw-r--r--@  1 root  wheel    181 Nov 17 13:47 PPDVersions.plist
-rw-r--r--@  1 root  wheel  36743 Nov 17 13:47 ProductMetadata.plist
-rw-r--r--   1 root  wheel    394 Nov 17 13:47 index.plist
drwxr-xr-x   9 root  wheel    306 Nov 17 13:47 zzzz091-30749 

Failed to install the updates -- until I deleted the two "Oct 12" folders.

On our end, we are going to attempt to mitigate this issue by having anything older than 2 weeks be deleted from /Library/Updates when msu runs with the hope that solves this problem.

I've reported my findings to Apple (we've had an open case on this since back in the 10.11 days) -- because we are now wondering if something like having the "Safari 11.0" package there keeps "Safari 11.0.1" -- and everything else -- from installing, but we are wondering if there's something on the munki-end of things that could also mitigate the ability for /Library/Updates to become a packrat for whatever reason?

I am literally thrilled out of my gourd to have finally (I hope) figured out why these Apple updates are failing to install so often and am curious to know if anybody following this thread would have the same results?)

[Gregory Neagle]

This of course continues to confirm my belief these are _softwareupdate_ bugs.  As for "what could Munki do to work around these bugs" -- answering this definitively would require accurately understanding and figuring out how to work around these issues _outside of Munki_. I don't think we are there yet. Certainly people have some promising theories and possible work arounds, but there is more to learn/understand/test.

-Greg

[Mike Solin]

Thanks, Steve and Greg!

I agree, I think this is a softwareupdate bug - when we see this issue, running softwareupdate manually seems to work.  Is MSC doing something that’s different than running softwareupdate manually?

Next time I come across a Mac exhibiting this behavior, I’m going to try deleting old updates from /Library/Updates, then installing via MSC.  If that works, maybe I can do the same - delete any stale updates from /Library/Updates on an ongoing basis, probably with a LaunchDaemon (if I can’t just piggyback on an existing Munki run).

Good find!  I’ll see if I can get more information the next time I see this happening.

Mike

-- 

mi...@mikesolin.com / @flammable

https://mikesolin.com

[Robinson Nuñez]

Hi Everyone

What I've noticed is that OS and security updates that get downloaded and not installed inside a (unkown) timeframe, fail. After the failed install, and sometimes restart, the updates get downloaded again and install ok. This could be some type of expiration by design or Apple replacing the updaters. I believe I've seen this in all updaters that require a restart.

Would be nice to get some real info from the source...

Thanks!!

Robinson

You received this message because you are subscribed to a topic in the Google Groups "munki-dev" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/munki-dev/E_0Xgxg2lNg/unsubscribe.
To unsubscribe from this group and all its topics, send an email to munki-dev+...@googlegroups.com.

[Steve Maser]

I thought about that, but in one of my tests, I had the user try installing and failing to install twice before deleting the two old installers and then the updates installed without (AFAICT) downloading the updates again.

We will have a better idea if our theory of purging the old updates works when the next round of Apple updates are released.  I have a list of computers that have generally had this problem for a *long time* after every set of Apple updates are released and we make them available.    We thought about purging the entire folder if it found anything "old" in it, but we're holding that one back until the next round.

[Steve Maser]

The other interesting thing we noticed as it appears that 10.13.1 updates always reports as a FAILED install -- when they are actually installing.

However, our mass rollout of 10.13 hasn't happened yet (and won't until 10.13.2 due to all the AD-related bugs), so this is in a sample size of about 30 at best.

This will happen:

Nov 17 2017 16:39:06 -0500 Installing available Apple Software Updates...
Nov 17 2017 16:39:12 -0500 Installing macOS 10.13.1 Update
Nov 17 2017 16:42:27 -0500     Done.
Nov 17 2017 16:42:27 -0500     You have installed one or more updates that requires that you restart your
Nov 17 2017 16:42:27 -0500     computer.  Please restart immediately.
Nov 17 2017 16:42:27 -0500 WARNING: Apple update macOS 10.13.1 Update, 091-39211 may have failed to install. No record of success or failure.

But the next msu run shows (on something we version-lock so it gives a different warning):

Nov 17 2017 17:42:44 -0500 WARNING: Rejected item hidemachkernel, version 1.1 with maximum os version required 10.9.99. Our OS version is 10.13.1.

All of my MSC-installed 10.13.x seed updates that I have tested through munki installs have also reported "failed" as well (and I just looked for this today, so I don't really have other details about it -- other than to say they those updates actually installed.)

Sep 28 2017 08:05:43 -0400 Apple Software Update install of macOS High Sierra 10.13.1 Developer Beta-1: FAILED for unknown reason

Oct 23 2017 15:56:45 -0400 Apple Software Update install of macOS High Sierra 10.13.1 Developer Beta-4: FAILED for unknown reason

Oct 26 2017 14:50:40 -0400 Apple Software Update install of macOS High Sierra 10.13.1 Developer Beta-5: FAILED for unknown reason

Nov 13 2017 16:44:28 -0500 Apple Software Update install of macOS High Sierra 10.13.2 Developer Beta-3: FAILED for unknown reason

Nov 16 2017 15:50:11 -0500 Apple Software Update install of macOS High Sierra 10.13.2 Developer Beta-4: FAILED for unknown reason

But that's probably for some completely different reason.   We don't have enough data to say if the 10.13.1 updates are reporting failing but *not* installing yet (like what happens on 10.11/10.12) because the number of machines running this 10.13 here is so small.   Maybe 10.13's "softwareupdate" is working better, but just reporting poorly...

[Gregory Neagle]

On Nov 18, 2017, at 8:14 AM, Steve Maser <ma...@umich.edu> wrote:

The other interesting thing we noticed as it appears that 10.13.1 updates always reports as a FAILED install -- when they are actually installing.

However, our mass rollout of 10.13 hasn't happened yet (and won't until 10.13.2 due to all the AD-related bugs), so this is in a sample size of about 30 at best.

This will happen:

Nov 17 2017 16:39:06 -0500 Installing available Apple Software Updates...
Nov 17 2017 16:39:12 -0500 Installing macOS 10.13.1 Update
Nov 17 2017 16:42:27 -0500     Done.
Nov 17 2017 16:42:27 -0500     You have installed one or more updates that requires that you restart your
Nov 17 2017 16:42:27 -0500     computer.  Please restart immediately.
Nov 17 2017 16:42:27 -0500 WARNING: Apple update macOS 10.13.1 Update, 091-39211 may have failed to install. No record of success or failure.

Note that that is not actually a failure or error.

softwareupdate doesn't provide clear/machine-readable success/failure info about individual updates. Munki simply parses the human-reable output from the tool. If the output is not what is expected/looked for you'll see that warning. Munki is telling you "I don't know if the update succeeded or failed".

But the next msu run shows (on something we version-lock so it gives a different warning):

Nov 17 2017 17:42:44 -0500 WARNING: Rejected item hidemachkernel, version 1.1 with maximum os version required 10.9.99. Our OS version is 10.13.1.

All of my MSC-installed 10.13.x seed updates that I have tested through munki installs have also reported "failed" as well (and I just looked for this today, so I don't really have other details about it -- other than to say they those updates actually installed.)

Sep 28 2017 08:05:43 -0400 Apple Software Update install of macOS High Sierra 10.13.1 Developer Beta-1: FAILED for unknown reason

Oct 23 2017 15:56:45 -0400 Apple Software Update install of macOS High Sierra 10.13.1 Developer Beta-4: FAILED for unknown reason

Oct 26 2017 14:50:40 -0400 Apple Software Update install of macOS High Sierra 10.13.1 Developer Beta-5: FAILED for unknown reason

Nov 13 2017 16:44:28 -0500 Apple Software Update install of macOS High Sierra 10.13.2 Developer Beta-3: FAILED for unknown reason

Nov 16 2017 15:50:11 -0500 Apple Software Update install of macOS High Sierra 10.13.2 Developer Beta-4: FAILED for unknown reason

But that's probably for some completely different reason.   We don't have enough data to say if the 10.13.1 updates are reporting failing but *not* installing yet (like what happens on 10.11/10.12) because the number of machines running this 10.13 here is so small.   Maybe 10.13's "softwareupdate" is working better, but just reporting poorly...

[Mr. Alan Siu]

For what it's worth, I have a test client that had an update downloaded in /Library/Updates from earlier today (so not stale), and the /Library/Managed Installs/Logs/Install.log still says:

Nov 28 2017 11:40:13 -0800 Apple Software Update install of Security Update 2017-001-10.12.6: FAILED for unknown reason

That happened through two Munki runs of logging out, trying to install the update, and rebooting.

I ran softwareupdate -d -a, and it actually downloaded the security update (instead of seeing that it exists). So maybe the already-downloaded update is stale somehow, even though it was downloaded today?

Alan Siu

Client Systems Analyst

St. Ignatius College Preparatory

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+unsubscribe@googlegroups.com.

[Steve Maser]

Yeah, we pushed out something that clears out anything "stale" after two weeks from /Library/Updates -- but we really won't know if this helps with the problem until the next round of OS updates comes out so we can see if this makes any difference or not (or whether or not we need to reduce that time...)   I'll update this thread if it looks like it may help here or not (in theory it would, but it's hard to say that just having it redownloaded again wouldn't result in the same problem for whatever reason...)

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+...@googlegroups.com.

[Matt Jarvis]

I'm manually packaging and munkiimport-ing the latest OS X update (10.13.2) to deploy with Munki and I have this curious behaviour:

- I run ManagedSoftwareUpdate (or open the Managed Software Center GUI)
- the package is downloaded
- I am prompted that the update requires a restart and am logged out
- the installation dialog appears, hums along pretty quickly, and then prompts me that a  restart is required
- the machine reboots
- I login, and the update has not been applied (machine is still on 10.13.1)

I can run this a number of times, and invariably on the 4th or 5th go (with better luck running managedsoftwareupdate from the terminal), the update works and when I am logged out, the installation process eventually shows me a black apple screen with a progress bar (2 minutes) and then reboots and I get another back apple screen with a progress bar (40 minutes) and when it finishes and I login, the update has successfully applied (machine is 10.13.2).

The /Library/Managed Installs/Logs/Install.log shows me that all 4 installations were successful from Munki's point of view:

Dec 11 2017 17:11:58 +1100 Install of MacOS 10.13.2 Combo Update-10.13.2.1.1.1512594190: SUCCESSFUL
Dec 11 2017 17:18:14 +1100 Install of MacOS 10.13.2 Combo Update-10.13.2.1.1.1512594190: SUCCESSFUL
Dec 11 2017 17:22:02 +1100 Install of MacOS 10.13.2 Combo Update-10.13.2.1.1.1512594190: SUCCESSFUL
Dec 11 2017 17:27:33 +1100 Install of MacOS 10.13.2 Combo Update-10.13.2.1.1.1512594190: SUCCESSFUL

I have the/var/log/install.log for both unsuccessful and successful installs, and it looks to me in the unsuccessful installs that the installation phases are skipped and I see an error 112 at the end:

2017-12-11 17:21:54+11 nb-204 installer[469]: JS: my.target.isDisallowedForCoreStorageOperations = false
2017-12-11 17:21:54+11 nb-204 installer[469]: recoveryPartitionVersionForVolume: could not get recovery version information for mount point /Volumes/Install macOS High Sierra: Unable to find boot helper partition. (-69737)
2017-12-11 17:21:54+11 nb-204 installer[469]: JS: my.target.isDisallowedForCoreStorageOperations = false
2017-12-11 17:21:54+11 nb-204 installer[469]: recoveryPartitionVersionForVolume: could not get recovery version information for mount point /Volumes/Install macOS High Sierra: Unable to find boot helper partition. (-69737)
2017-12-11 17:21:54+11 nb-204 installer[469]: JS: my.target.isDisallowedForCoreStorageOperations = false
2017-12-11 17:21:54+11 nb-204 installer[469]: JS: my.target.isDisallowedForCoreStorageOperations = false
2017-12-11 17:21:54+11 nb-204 installer[469]: Product archive /private/tmp/dmg.k42jFj/macOSUpdCombo10.13.2.pkg trustLevel=501
2017-12-11 17:21:54+11 nb-204 installer[469]: Will do post-logout install for package with trust 501
2017-12-11 17:21:54+11 nb-204 installer[469]: Starting post logout install with document at path /private/tmp/dmg.k42jFj/macOSUpdCombo10.13.2.pkg
2017-12-11 17:21:54+11 nb-204 installer[469]: Product archive /private/tmp/dmg.k42jFj/macOSUpdCombo10.13.2.pkg trustLevel=501
2017-12-11 17:21:54+11 nb-204 softwareupdated[395]: Adding client SUUpdateServiceClient pid=469, uid=0, installAuth=NO rights=(), transactions=0 (/usr/sbin/installer)
2017-12-11 17:21:54+11 nb-204 system_installd[479]: installd: Starting
2017-12-11 17:21:54+11 nb-204 system_installd[479]: installd: uid=0, euid=0
2017-12-11 17:21:54+11 nb-204 system_installd[479]: PackageKit: Adding client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:21:55+11 nb-204 softwareupdated[395]: Attempting to adopt manual product: macOS 10.13.2 Update Combo
2017-12-11 17:21:55+11 nb-204 softwareupdated[395]: Existing adopted product will be replaced
2017-12-11 17:21:55+11 nb-204 softwareupdated[395]: Removed local product for _ManualUpdate (1)
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: JS: my.target.isDisallowedForCoreStorageOperations = false
2017-12-11 17:22:01+11 nb-204 suhelperd[396]: Verifying package at path: /Library/Updates/_ManualUpdate/macOSUpdCombo10.13.2.pkg
2017-12-11 17:22:01+11 nb-204 suhelperd[396]: packageWithPath returned nil!
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Token successfully added to approvedStashingTokens set.
2017-12-11 17:22:01+11 nb-204 installer[469]: ManualAdoption: Adopted /private/tmp/dmg.k42jFj/macOSUpdCombo10.13.2.pkg
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Adding client SUUpdateServiceClient pid=494, uid=0, installAuth=NO rights=(), transactions=0 (/System/Library/PrivateFrameworks/SoftwareUpdate.framework/Versions/A/XPCServices/ManualProductStasherService.xpc/Contents/MacOS/ManualProductStasherService)
2017-12-11 17:22:01+11 nb-204 system_installd[479]: PackageKit: Adding client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:01+11 nb-204 installer[469]: ManualAdoption: Authorization established successfully for ManualProductStasherService
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Token consumption request is valid and is found in the trusted cache set, stashing permitted!
2017-12-11 17:22:01+11 nb-204 ManualProductStasherService[494]: Can't stash: 0x80011006
2017-12-11 17:22:01+11 nb-204 installer[469]: ManualAdoption: Stashing failed!
2017-12-11 17:22:01+11 nb-204 ManualProductStasherService[494]: ManualProductStasherService: InvalidationHandler Called, connectingPid:469
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Removing client SUUpdateServiceClient pid=494, uid=0, installAuth=YES rights=(system.install.apple-software, system.install.software, com.apple.SoftwareUpdate.modify-settings), transactions=0 (/System/Library/PrivateFrameworks/SoftwareUpdate.framework/Versions/A/XPCServices/ManualProductStasherService.xpc/Contents/MacOS/ManualProductStasherService)
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Successfully holding Pre-logout Display sleep assertion for 15 minutes
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Set products to install at logout _ManualUpdate (nowIsLater = FALSE)
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: SUUpdateSession: Skipping preflighting firmware since we're not on relevant hardware
2017-12-11 17:22:01+11 nb-204 installer[469]: Update was adopted
2017-12-11 17:22:01+11 nb-204 softwareupdated[395]: Removing client SUUpdateServiceClient pid=469, uid=0, installAuth=YES rights=(system.install.apple-software, system.install.software, com.apple.SoftwareUpdate.modify-settings), transactions=0 (/usr/sbin/installer)
2017-12-11 17:22:05+11 nb-204 bootinstalld[211]: BootTimeInstall: Client loginwindow[88]: Disconnected.
2017-12-11 17:22:05+11 nb-204 softwareupdated[395]: Removing client SUUpdateServiceClient pid=400, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/PrivateFrameworks/CommerceKit.framework/Versions/A/Resources/storeassetd)
2017-12-11 17:22:05+11 nb-204 softwareupdated[395]: Removing client SUUpdateServiceClient pid=394, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_notify_agent)
2017-12-11 17:22:05+11 nb-204 Software Update[547]: AssertionMgr: Take com.apple.SoftwareUpdate.RootModeInstaller assertion with type MaintenanceWake for pid 547, id 0x810B
2017-12-11 17:22:05+11 nb-204 Software Update[547]: AssertionMgr: Take com.apple.SoftwareUpdate.RootModeInstaller.DisplayAwake assertion with type PreventUserIdleDisplaySleep for pid 547, id 0x810C
2017-12-11 17:22:05+11 nb-204 Software Update[547]: authorizeWithEmptyAuthorizationForRights: Requesting provided rights: 16
2017-12-11 17:22:05+11 nb-204 softwareupdated[395]: Adding client SUUpdateServiceClient pid=547, uid=0, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/MacOS/Software Update)
2017-12-11 17:22:05+11 nb-204 system_installd[479]: PackageKit: Adding client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:05+11 nb-204 Software Update[547]: Configuring installer progress phases
2017-12-11 17:22:05+11 nb-204 Installer Progress[548]: Progress UI App Starting
2017-12-11 17:22:06+11 nb-204 suhelperd[396]: isModernOS = 1
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASGetCurrentInstallPhaseList: Unable to get phases
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASGetCurrentInstallPhase: Unable to get the current phase name
2017-12-11 17:22:06+11 nb-204 suhelperd[396]: Progress phases configured for - FLO: NO, healing: NO, BaseSystem prods: 1, Non-BaseSystem prods: 0
                       Phase 1: Software Update Post Logout - 9.6
                       Phase 2: Restarting - 2
                       Phase 3: B1 - 8.64
                       Phase 4: LC - 4.32
                       Phase 5: OS - 73.44
                       Phase 6: Placeholder (FLO + Healing)  - 2
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: phaseName = (null)
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: No matching products found while calculating disk space required
2017-12-11 17:22:06+11 nb-204 Software Update[547]: Starting post-logout install of _ManualUpdate
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: _currentPhase = "(null)", _phases = (null)
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASClearInstallProgress: Clearing Registry
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        }
    )
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Software Update[547]: FLO Enabled = NO
2017-12-11 17:22:06+11 nb-204 Software Update[547]: Done taking requests
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        }
    )
2017-12-11 17:22:06+11 nb-204 Software Update[547]: Progress phase - Software Update Post Logout init
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Software Update[547]: ISAP: Show progress UI called
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Boot 1";
            InstallPhasePercentageKey = 9;
        }
    )
2017-12-11 17:22:06+11 nb-204 Software Update[547]: OS Snapshot status: Initiated
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Boot 1";
            InstallPhasePercentageKey = 9;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Language Chooser";
            InstallPhasePercentageKey = 4;
        }
    )
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Boot 1";
            InstallPhasePercentageKey = 9;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Language Chooser";
            InstallPhasePercentageKey = 4;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "OS Installer";
            InstallPhasePercentageKey = 73;
        }
    )
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Boot 1";
            InstallPhasePercentageKey = 9;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Language Chooser";
            InstallPhasePercentageKey = 4;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "OS Installer";
            InstallPhasePercentageKey = 73;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Placeholder;
            InstallPhasePercentageKey = 2;
        }
    )
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASGetCurrentInstallPhaseList: phases = (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Boot 1";
            InstallPhasePercentageKey = 9;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Language Chooser";
            InstallPhasePercentageKey = 4;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "OS Installer";
            InstallPhasePercentageKey = 73;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Placeholder;
            InstallPhasePercentageKey = 2;
        }
    )
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASGetCurrentInstallPhase: Current phase name is "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: phaseName = Software Update Post Logout
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: _currentPhase = "<IASPPhase: 0x7ffd39c1ce30: 'Software Update Post Logout', percentage 10.0, delay 0>", _phases = (
        "<IASPPhase: 0x7ffd39c1ce30: 'Software Update Post Logout', percentage 10.0, delay 0>",
        "<IASPPhase: 0x7ffd39c28d70: 'Restarting', percentage 2.0, delay 0>",
        "<IASPPhase: 0x7ffd39c28d90: 'Boot 1', percentage 9.0, delay 0>",
        "<IASPPhase: 0x7ffd39c29fa0: 'Language Chooser', percentage 4.0, delay 0>",
        "<IASPPhase: 0x7ffd39c29fc0: 'OS Installer', percentage 73.0, delay 0>",
        "<IASPPhase: 0x7ffd39c29f80: 'Placeholder', percentage 2.0, delay 0>"
    )
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Showing Progress UI
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: There are 0 window(s) and 1 display(s), 1 window(s) will be added
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Created a window at {{0, 0}, {2560, 1440}}
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Setting window alpha values to 0.0
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Ordering windows front
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Ordering windows front
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Setting window alpha values to 1.0
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Progress app is loading…
2017-12-11 17:22:06+11 nb-204 Installer Progress[548]: Progress app is running…
2017-12-11 17:22:06+11 nb-204 Software Update[547]: OS Snapshot status: Succeeded. Snapshot date: 2017-12-11 06:22:06 +0000.
2017-12-11 17:22:06+11 nb-204 Software Update[547]: Starting root mode (post-logout) update(s)
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: SUUpdateSession startUpdateForProducts:<_SUManualAdoptedProduct: _ManualUpdate> inForeground: YES stageOnly: NO
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: SoftwareUpdate: Added foreground transaction [0x1] for _ManualUpdate
2017-12-11 17:22:06+11 nb-204 installd[550]: installd: Starting
2017-12-11 17:22:06+11 nb-204 installd[550]: installd: uid=0, euid=0
2017-12-11 17:22:06+11 nb-204 installd[550]: PackageKit: Adding client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:06+11 nb-204 installd[550]: PackageKit: Removing client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: Removing client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: Removing client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: Removing client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: Changing status (_installProducts) for key _ManualUpdate from "downloaded" to "waiting to install"
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: JS: my.target.isDisallowedForCoreStorageOperations = false
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: Changing status (_installProducts) for key _ManualUpdate from "waiting to install" to "installing"
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: Installing - all non-BaseSystem path products
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: Adding client PKInstallDaemonClient pid=395, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)
2017-12-11 17:22:06+11 nb-204 softwareupdated[395]: PackageKit: Enqueuing install with client-specified quality of service (utility)
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: ----- Begin install -----
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: request=PKInstallRequest <2 packages, destination=/>
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: packages=(
        "PKLeopardPackage <id=com.apple.pkg.macOSUpdCombo10.13.2.RecoveryHDUpdate.17C89, version=1.0.0.0, url=file:///Library/Updates/_ManualUpdate/macOSUpdCombo10.13.2.pkg#macOSUpdCombo10.13.2.RecoveryHDUpdate.pkg>",
        "PKLeopardPackage <id=com.apple.pkg.FirmwareUpdate, version=10.13.2.1, url=file:///Library/Updates/_ManualUpdate/macOSUpdCombo10.13.2.pkg#FirmwareUpdate.pkg>"
    )
2017-12-11 17:22:06+11 nb-204 system_installd[479]: PackageKit: Failed to clear quarantine on Apple-signed package PKLeopardPackage <id=com.apple.pkg.FirmwareUpdate, version=10.13.2.1, url=file:///Library/Updates/_ManualUpdate/macOSUpdCombo10.13.2.pkg#FirmwareUpdate.pkg>: Item not quarantined (-1)
2017-12-11 17:22:07+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: prevent user idle system sleep
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: suspending Spotlight indexing
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: suspending backupd
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: Executing script "preinstall" in /private/tmp/PKInstallSandbox.3Kx7Sx/Scripts/com.apple.pkg.FirmwareUpdate.IGUA3Z
2017-12-11 17:22:07+11 nb-204 install_monitor[553]: Temporarily excluding: /Applications, /Library, /System, /bin, /private, /sbin, /usr
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: Using system content trashcan path /.PKInstallSandboxManager-SystemSoftware/D4D26E99-39DF-41DC-9B81-8CA32FC662BA.activeSandbox/Trashes for sandbox /.PKInstallSandboxManager-SystemSoftware/D4D26E99-39DF-41DC-9B81-8CA32FC662BA.activeSandbox
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: Shoving /.PKInstallSandboxManager-SystemSoftware/D4D26E99-39DF-41DC-9B81-8CA32FC662BA.activeSandbox/Root (0 items) to /
2017-12-11 17:22:07+11 nb-204 system_installd[479]: PackageKit: Executing script "replaceRecovery" in /private/tmp/PKInstallSandbox.3Kx7Sx/Scripts/com.apple.pkg.macOSUpdCombo10.13.2.RecoveryHDUpdate.17C89.GlQUzC
2017-12-11 17:22:07+11 nb-204 system_installd[479]: replaceRecovery: Attempting to create temporary mount point
2017-12-11 17:22:07+11 nb-204 system_installd[479]: replaceRecovery: Attempting mount of /Library/Updates/_ManualUpdate/macOSUpdCombo10.13.2.pkg to /var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/tmp.TiXBHCbA
2017-12-11 17:22:08+11 nb-204 system_installd[479]: replaceRecovery: Checksumming Protective Master Boot Record (MBR : 0)…
2017-12-11 17:22:08+11 nb-204 system_installd[479]: replaceRecovery: Protective Master Boot Record (MBR :: verified   CRC32 $749EC771
2017-12-11 17:22:08+11 nb-204 system_installd[479]: replaceRecovery: Checksumming GPT Header (Primary GPT Header : 1)…
2017-12-11 17:22:08+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:09+11 nb-204 system_installd[479]: replaceRecovery:  GPT Header (Primary GPT Header : 1): verified   CRC32 $1DF305F8
2017-12-11 17:22:09+11 nb-204 system_installd[479]: replaceRecovery: Checksumming GPT Partition Data (Primary GPT Table : 2)…
2017-12-11 17:22:09+11 nb-204 system_installd[479]: replaceRecovery: GPT Partition Data (Primary GPT Tabl: verified   CRC32 $222E483B
2017-12-11 17:22:09+11 nb-204 system_installd[479]: replaceRecovery: Checksumming  (Apple_Free : 3)…
2017-12-11 17:22:09+11 nb-204 Installer Progress[548]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:10+11 nb-204 system_installd[479]: replaceRecovery:                     (Apple_Free : 3): verified   CRC32 $00000000
2017-12-11 17:22:10+11 nb-204 system_installd[479]: replaceRecovery: Checksumming disk image (Apple_HFS : 4)…
2017-12-11 17:22:29+11 macadmins-iMac Installer Progress[67]: Progress UI App Starting
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASGetCurrentInstallPhaseList: phases = (
            {
            ConclusionDelay = 0;
            InstallPhase = "Software Update Post Logout";
            InstallPhasePercentageKey = 10;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Restarting;
            InstallPhasePercentageKey = 2;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Boot 1";
            InstallPhasePercentageKey = 9;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "Language Chooser";
            InstallPhasePercentageKey = 4;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = "OS Installer";
            InstallPhasePercentageKey = 73;
        },
            {
            ConclusionDelay = 0;
            InstallPhase = Placeholder;
            InstallPhasePercentageKey = 2;
        }
    )
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASGetCurrentInstallPhase: Current phase name is "Software Update Post Logout"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: phaseName = Software Update Post Logout
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "Software Update Post Logout"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: _currentPhase = "<IASPPhase: 0x7fc416e33a40: 'Software Update Post Logout', percentage 10.0, delay 0>", _phases = (
        "<IASPPhase: 0x7fc416e33a40: 'Software Update Post Logout', percentage 10.0, delay 0>",
        "<IASPPhase: 0x7fc416c33bb0: 'Restarting', percentage 2.0, delay 0>",
        "<IASPPhase: 0x7fc416c12b10: 'Boot 1', percentage 9.0, delay 0>",
        "<IASPPhase: 0x7fc416c30130: 'Language Chooser', percentage 4.0, delay 0>",
        "<IASPPhase: 0x7fc416c33dd0: 'OS Installer', percentage 73.0, delay 0>",
        "<IASPPhase: 0x7fc416c2fb40: 'Placeholder', percentage 2.0, delay 0>"
    )
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Progress app is loading…
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Progress app is running…
2017-12-11 17:22:31+11 macadmins-iMac bootinstalld[211]: BootTimeInstall: Client loginwindow[88]: Connected.
2017-12-11 17:22:31+11 macadmins-iMac loginwindow[88]: isModernOS = 1
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASClearInstallProgress: Clearing Registry
2017-12-11 17:22:31+11 macadmins-iMac loginwindow[88]: ISAP: Show progress UI called
2017-12-11 17:22:31+11 macadmins-iMac loginwindow[88]: ISAP: Done with Phase "IOKit Boot"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "IOKit Boot";
            InstallPhasePercentageKey = 4;
        }
    )
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "IOKit Boot"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhaseList: phases set to (
            {
            ConclusionDelay = 0;
            InstallPhase = "IOKit Boot";
            InstallPhasePercentageKey = 4;
        },
            {
            ConclusionDelay = "-1";
            InstallPhase = "loginwindow Boot";
            InstallPhasePercentageKey = 96;
        }
    )
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "IOKit Boot"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASGetCurrentInstallPhaseList: phases = (
            {
            ConclusionDelay = 0;
            InstallPhase = "IOKit Boot";
            InstallPhasePercentageKey = 4;
        },
            {
            ConclusionDelay = "-1";
            InstallPhase = "loginwindow Boot";
            InstallPhasePercentageKey = 96;
        }
    )
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASGetCurrentInstallPhase: Current phase name is "IOKit Boot"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: phaseName = IOKit Boot
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "IOKit Boot"
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: _currentPhase = "<IASPPhase: 0x7fc416e42390: 'IOKit Boot', percentage 4.0, delay 0>", _phases = (
        "<IASPPhase: 0x7fc416e42390: 'IOKit Boot', percentage 4.0, delay 0>",
        "<IASPPhase: 0x7fc416e42200: 'loginwindow Boot', percentage 96.0, delay -1>"
    )
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Showing Progress UI
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: There are 0 window(s) and 1 display(s), 1 window(s) will be added
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Created a window at {{0, 0}, {2560, 1440}}
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Setting window alpha values to 0.0
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Ordering windows front
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Ordering windows front
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: Setting window alpha values to 1.0
2017-12-11 17:22:31+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "IOKit Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: Done with phase = "IOKit Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "IOKit Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac loginwindow[88]: ISAP: Done with Phase "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: Done with phase = "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASSetCurrentInstallPhase: Current phase name set to "loginwindow Boot"
2017-12-11 17:22:32+11 macadmins-iMac Installer Progress[67]: IASClearInstallProgress: Clearing Registry
2017-12-11 17:22:33+11 macadmins-iMac loginwindow[88]: ISAP: hide progress UI called
2017-12-11 17:22:33+11 macadmins-iMac Installer Progress[67]: Hiding Progress UI
2017-12-11 17:22:33+11 macadmins-iMac Installer Progress[67]: Setting window alpha values to 0.0
2017-12-11 17:22:33+11 macadmins-iMac Installer Progress[67]: Ordering windows out
2017-12-11 17:22:34+11 macadmins-iMac Installer Progress[67]: Quitting: There are no connected processes and there is no UI showing
2017-12-11 17:22:34+11 macadmins-iMac Installer Progress[67]: Quiting Progress App
2017-12-11 17:24:50+11 nb-204 softwareupdate_notify_agent[397]: Handling notification event: LoginDone
2017-12-11 17:24:50+11 nb-204 softwareupdate_notify_agent[397]: AssertionMgr: Take com.apple.softwareupdate.NotifyAgentAssertion-LoginDone assertion with type BackgroundTask for pid 397, id 0x80B1
2017-12-11 17:24:50+11 nb-204 softwareupdated[398]: softwareupdated: Starting with build 10.13.1 (17B48)
2017-12-11 17:24:50+11 nb-204 softwareupdated[398]: Initiating startup cleanup
2017-12-11 17:24:50+11 nb-204 softwareupdated[398]: This could possibly be a restart after a crash.
2017-12-11 17:24:50+11 nb-204 softwareupdated[398]: authorizeWithEmptyAuthorizationForRights: Requesting provided rights: 8
2017-12-11 17:24:51+11 nb-204 suhelperd[399]: SUCleanup: /Library/Updates/AtomicUpdates - 0, /private/var/db/.AtomicSUStatus - 0.
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: authorizeWithEmptyAuthorizationForRights: Requesting provided rights: 1
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: /Library/Bundles does not exist - watching for directory creation
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: Previous System Version : 10.13.1 (17B48), Current System Version : 10.13.1 (17B48)
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: SoftwareUpdate: Fire periodic check after upgrade to 10.13.1 (17B48)
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: BackgroundActivity: Scheduling one-time background activity in approx 15 minutes
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: Adding client SUUpdateServiceClient pid=397, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_notify_agent)
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: BackgroundActivity: Activity check-in with Interval 21600
2017-12-11 17:24:51+11 nb-204 softwareupdated[398]: xpc_add_bundle /System/Library/PrivateFrameworks/SoftwareUpdate.framework/XPCServices/ManualProductStasherService.xpc
2017-12-11 17:24:51+11 nb-204 softwareupdate_notify_agent[397]: Notifying with params: {
        PostLogoutUpdatesInstalled =     {
            "_ManualUpdate" =         {
                ErrorCode = 112;
                ErrorDomain = PKInstallErrorDomain;
                InstalledLater = 0;
                State = Error;
            };
        };
        UpdateNotificationsOnly = 1;
    }

I've tried this on a few machines now, an iMac, a MacBook and my test VM and this non-deterministic behaviour occurs on all of them.

[Steve Maser]

So what we have (successfully so far) done is set up something that deletes any directories in /Library/Updates that are older than "mtime +5".

This forces a redownload of the Apple packages and -- so far -- the results have been promising for subsequent attempts at reinstalls of those updates.

I have an open case with Apple on this and -- since we were able to find a computer where this happens going from 10.13.1 to 10.13.2 -- they are trying to figure out what's going on (as, you know, they won't fix older OSes...)  

Our initial theory that -- maybe -- the initial download did not get the full package -- was not borne out by the logs we sent them.    

If you have something that is *not Filevaulted* -- let me know as I'd append that to my case.  They think they've only seen this on FV'ed macs.   

[Mr. Alan Siu]

I do have some shared machines (lab iMacs) that are not FileVaulted, and I can't recall ever seeing an Apple update not install on those machines. It's almost always a FileVaulted machine.

Alan Siu

Client Systems Analyst

St. Ignatius College Preparatory

--

Find related discussion groups here:
https://github.com/munki/munki/wiki/Discussion-Group
---
You received this message because you are subscribed to the Google Groups "munki-dev" group.

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+unsubscribe@googlegroups.com.

[Stephen Johnson]

Steve, would you please share your method for deleting the updates? I've thought on doing something similar but would appreciate seeing how you have implemented it.

Thx

[Henning Kessler]

Hi, I have this issue with non-FileVaulted machines...

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+...@googlegroups.com.

[Paul Hildahl]

I have lab machines and laptop carts that are not FileVaulted who have the issue. They are currently on 10.12.6

[Steve Maser]

We have a number of scripts that do a variety of things every time managesoftwareupdate automatically runs.

One of the scripts now deletes any folders in /Library/Updates after X days (so a basic "find folder -mtime 5 rm -rf <result>") command.

I can't say this is 100% effective.  I've seen users have to have the Apple update folders delete more than one time before they install correctly.

[Steve Maser]

Henning and/or Paul, can you get a sysdiagnose from a computer doing this soon after you make Apple updates available and where it fails for a user that is not FileVaulted?

I'd love to append a sysdiagnose like that to my open case!

- Steve

[Michal Moravec]

Does deleting files from /Library/Updates help with installing successfully on the first try?

Coud you post your results?

[Steve Maser]

So we still don't actually know *why* there is a failure on some computers.    It's not lack of free disk space.   it's not based on hardware model.   We don't think it's limited to FileVaulted computers entirely.   It's not a function of whether or not there are other non-Apple updates to concurrently install.

It seems like for the vast majority of our systems (as far as we can tell), the upgrades *are working* on the first try (we have 7000+ systems running 10.11-10.13 currently with about 80% of those checking in daily.) -- for example we have a bunch of lab macs that check for updates every night and just about all of them install the Apple updates without issue (meaning we release updates Thursday night and they are downloaded/installed by Friday/Saturday morning -- depending on the lab -- without us having to delete anything from /Library/Updates.  It just works.

I've been tracking (for quite some time now) update percentages daily after we release Apple OS updates to everybody and in general we see about 30-35% successful install rate after 5 days -- which is before we would start clearing out /Library/Updates.  (This is because everything is optional for 2 weeks.)   What we do *not* track is when *every* system initially downloads the Apple Updates and whether or not they install them within the first 5 days before we'd sweep out whatever was downloaded.

What we haven't figured out is why it appears to be the *same computers* having the problems installing the Apple Updates each time (and, then again, it's not exactly *each and every time*).

But we are fairly confident that since setting things to purge /Library/Updates after every 5+ days, this has allowed those systems where it fails to install in those first 5 days after release day to successfully install them on their subsequent attempt (or on the day two weeks+ later when we have the force install day -- for macs that are active daily, if they wait for our Force Install day (2 weeks after release), it usually means /Library/Updates would have been purged twice by then.   

At this point, all of our data about machines we've been able to track that seemingly have consistent problems has been sent to Apple and Engineering has it.  What we don't know is if they can replicate it in-house.   The only feedback I've really gotten from them was that the *initial downloads* from some of these troubled computers were not reporting as "partial" downloads (which was our initial theory -- that they were being presented in MSC as available, but not all package contents were actually downloaded) and that nothing jumped out as to why these were failing to install.   (10.13.2 was our first official release, so we are tracking that to see if there's any difference, but I've sent logs where the Supplemental Update failed to install on some systems after we released it, too -- so 10.13.2 is still "broken" in this sense.)

I don't know if this will help anybody -- I think we've done what we can (short of thinking about reducing the number of days to purge /Library/Updates even further).    We are waiting for the next round of security updates/10.13.3 to make that decision if the numbers don't change much.

The rest of it is up to Apple?

But as I've said before -- if you are seeing this problem in your org, PLEASE OPEN A CASE WITH APPLE.   Our case is *one case* -- even though this could be affecting hundreds of computers.   They need to hear from other orgs to get attention to this.

- Steve

[Matter]

We've just moved from Apple SUS to reposado hoping to solve these issues but no luck. We've seen an increase of warnings "XXX-XXXXX may have failed to install. No record of success or failure." Safari 11.0.2 build 2 is currently giving the most warnings. All workstations are encrypted so can't help there. I'll also try to purge old items from /Library/Updates. 

[Steve Maser]

FWIW -- we get the warning on any 10.13 update -- even though it (almost always) installs.  So that's why logging this on so many computers to get stats of success/failure rates after purging /Library/Updates isn't as easy as you might think.

[Gregory Neagle]

On Jan 19, 2018, at 8:26 AM, Steve Maser <ma...@umich.edu> wrote:

FWIW -- we get the warning on any 10.13 update -- even though it (almost always) installs.

Interesting. We're _not_ seeing that.

 So that's why logging this on so many computers to get stats of success/failure rates after purging /Library/Updates isn't as easy as you might think.

On Friday, January 19, 2018 at 8:55:44 AM UTC-5, Matter wrote:

We've just moved from Apple SUS to reposado hoping to solve these issues but no luck. We've seen an increase of warnings "XXX-XXXXX may have failed to install. No record of success or failure." Safari 11.0.2 build 2 is currently giving the most warnings. All workstations are encrypted so can't help there. I'll also try to purge old items from /Library/Updates. 

--

[Mike Solin]

I’m seeing this with the 10.13.2 Supplemental Update, but we only have a dozen Macs running 10.13 at the moment.

Steve, for those of us without an enterprise support contract, what do you suggest?  Which logs would be appropriate to gather, and where should I send them?

Mike

--

mi...@mikesolin.com / @flammable

http://mikesolin.com

--
Find related discussion groups here:
https://github.com/munki/munki/wiki/Discussion-Group
---
You received this message because you are subscribed to the Google Groups "munki-dev" group.

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+unsubscribe@googlegroups.com.

[Gregory Neagle]

You only need a Developer Account to access bugreporter.apple.com...

-Greg

To unsubscribe from this group and stop receiving emails from it, send an email to munki-dev+...@googlegroups.com.

[Steve Maser]

It's pretty consistent for us:

Jan 19 2018 13:52:44 -0500 Installing available Apple Software Updates...

Jan 19 2018 13:52:45 -0500 Installing macOS High Sierra 10.13.2 Supplemental Update

Jan 19 2018 13:53:02 -0500     Done.

Jan 19 2018 13:53:02 -0500     You have installed one or more updates that requires that you restart your

Jan 19 2018 13:53:02 -0500     computer.  Please restart immediately.

Jan 19 2018 13:53:02 -0500 WARNING: Apple update macOS High Sierra 10.13.2 Supplemental Update, 091-58876 may have failed to install. No record of success or failure.

Jan 19 2018 13:53:02 -0500 Finishing...

And this is after a successful install -- not one of the failed installs.

(shrug)

[Gregory Neagle]

Oh this might be because the only way Munki gets any indication of success or failure of softwareupdate installs is by parsing the log output. If it doesn't see what it expects to see to indicate success (or failure), it can only say "WARNING: Apple update macOS High Sierra 10.13.2 Supplemental Update, 091-58876 may have failed to install. No record of success or failure."

https://github.com/munki/munki/blob/master/code/client/munkilib/appleupdates/au.py#L599-L628

-Greg

[Matter]

So I chose to go with the bold approach: delete the /Library/Update folder if it's older then one day. Today we have a force install date on the Security Update 2018-001. I've seen at least one workstation fail and I noticed that it's caching the metadata and language distribution files multiple times. Summary of logfile of the first run:

Feb 06 2018 16:41:56 +0100     Removing /Library/Updates/, creation date Sun Jul 31 00:51:26 CEST 2016 (my own script)

...

Feb 06 2018 16:41:56 +0100 Apple update catalog has changed.

Feb 06 2018 16:41:56 +0100 Checking for available Apple Software Updates...

Feb 06 2018 16:41:58 +0100     Finding available software

Feb 06 2018 16:41:58 +0100     Downloading Security Update 2018-001

Feb 06 2018 16:42:05 +0100     Downloaded Security Update 2018-001

Feb 06 2018 16:42:05 +0100     Done.

Feb 06 2018 16:42:05 +0100     Caching metadata for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching package metadata for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching package metadata for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching package metadata for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching package metadata for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching Spanish distribution for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching he distribution for product ID 091-62747

Feb 06 2018 16:42:05 +0100     Caching ko distribution for product ID 091-62747

etc...

Summary of second run:

Feb 07 2018 10:24:41 +0100 Apple update catalog has changed.

Feb 07 2018 10:24:41 +0100 Checking for available Apple Software Updates...

Feb 07 2018 10:24:42 +0100     Finding available software

Feb 07 2018 10:24:42 +0100     Downloaded Security Update 2018-001

Feb 07 2018 10:24:42 +0100     Done.

Feb 07 2018 10:24:42 +0100     Caching metadata for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching package metadata for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching package metadata for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching package metadata for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching package metadata for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching Spanish distribution for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching he distribution for product ID 091-62747

Feb 07 2018 10:24:42 +0100     Caching ko distribution for product ID 091-62747

etc...

So it says the catalog has changed, but we haven't changed anything. How does munki determine this change? My guess is it checks the timestamp on the catalog. If so, could this have changed by the repo_sync process. Our repo_sync runs once a day at 03:00 AM so that's exactly between the two managedsoftwareupdate runs.

It doesn't seem to re-download the update since it directly says "Downloaded" but it keeps caching those other files. Could this harm the actual update? In the /var/log/install.log I see the following (known) error:

softwareupdated[226]: SoftwareUpdate: Invalid or incomplete local product 091-62747

softwareupdated[226]: Removing local product after found to be incomplete

softwareupdated[226]: Removed local product for 091-62747 (1)

This update has been downloaded just one day ago. Since the Update folder was recreated by the process it's safe to say there were no older updates in there.

[Ben Goodstein]

munki compares the SHA-256 hash of the cached sucatalog vs. what it can download and forces a check if they are different.

https://github.com/munki/munki/blob/e05b5798b675581d386e6f7ee587ba69f637d4da/code/client/munkilib/appleupdates/au.py#L226-L230

--
Ben Goodstein
Technical Leader (Apple)

Endpoint Device Management Services
IT Services, University of Oxford
https://www.it.ox.ac.uk

--

[Matt Rittorno]

I had this issue when installing HighSierraSecurityUpdate006 (update would restart system but didn't install). I was able to work around by making the pkg a managed install instead of an optional install in the manifest.

And the aforementioned workaround also worked: softwareupdate -i -a

So I concur this is an apple bug in my situation; Managed Software Center is dealing with optional installs of apple updates incorrectly.

To unsubscribe from this group and stop receiving emails from it, send an email to munk...@googlegroups.com.