Munki 3.1 testing and feedback needed

[Gregory Neagle]

I really want to release Munki 3.1 before or concurrent with the High Sierra release.

The feedback I've gotten so far on the Release Candidates has been so thin that I don't feel very confident that all the new features work as expected/designed.

Some things I'd love to hear about:

- Has anyone successfully used Munki 3.1 to upgrade a machine to High Sierra?
- Has anyone tried this with a machine encrypted with FileVault2? Did post-os-install bootstrapping at the loginwindow work as expected?
- If post-os-install bootstrapping at the loginwindow worked as expected on a FV2-encrypted machine, on a subsequent reboot, did the machine proceed from disk unlock into account login as expected?
- Has anyone tested authorized restarts with this workflow with Munki 3.1?

- Has anyone tested this feature: "Managed Software Center.app can now optionally show optional installs and updates that apply to macOS versions higher than the currently installed version."? Does it behave as expected?

Hoping for _some_ data about these...

-Greg

[Ben Goodstein]

> On 8 Sep 2017, at 21:53, Gregory Neagle <gregn...@mac.com> wrote:
>
> I really want to release Munki 3.1 before or concurrent with the High Sierra release.
>
> The feedback I've gotten so far on the Release Candidates has been so thin that I don't feel very confident that all the new features work as expected/designed.
>

> Some things I'd love to hear about:
>
> - Has anyone successfully used Munki 3.1 to upgrade a machine to High Sierra?
> - Has anyone tried this with a machine encrypted with FileVault2? Did post-os-install bootstrapping at the loginwindow work as expected?

Preliminary testing on a FileVaulted 10.12VM upgraded to 10.13B 17A360a (optional_install) using munki 3.1RC3 showed that managedsoftwareupdate tried to run in checkandinstallatstartup mode immediately after setting up the OS upgrade and before the first reboot, resulting in a second run of the osinstaller and didn't run after the OS was upgraded. Attaching the VM's msu.log - interesting stuff is at the end. Let me know if you need more detail.

[Gregory Neagle]

I haven't seen similar behavior on my physical test hardware, but in the logs of a recent test I did see something strange which becomes a bit clearer with this report.

Let the investigations begin!

-Greg

[Gregory Neagle]

One thing that occurs to me is that the physical machine I've been testing on the most always has FV active, as I was also testing the DisableFDEAutoLogin stuff. The post-macos-install-setup code paths are different when FV is active and we think we can do an auth restart; perhaps there is a logic error, combined with some different behaviors from 10.13's startosinstall that results in the needed reboot after startosinstall not happening -- at least in some cases.

-Greg

[Gregory Neagle]

On Sep 8, 2017, at 7:48 PM, Gregory Neagle <gregn...@mac.com> wrote:

Just tried a 10.12.6->10.13 upgrade with Munki 3.1.0.3422 on a VMware Fusion VM (no FileVault) and it proceeded as expected: logout, setup of macOS install, reboot, install of High Sierra beta. The install still has 20+ to go, so I'll examine the ManagedSoftwareUpdate.log after it completes.

-Greg

[Gregory Neagle]

Here's the log, which looks pretty much as I expect:

Sep 09 2017 16:40:03 -0700 ### Beginning os installer session ###

Sep 09 2017 16:40:03 -0700 Starting macOS upgrade...

Sep 09 2017 16:40:03 -0700     Mounting disk image Install macOS High Sierra Beta-10.13.dmg

Sep 09 2017 16:40:21 -0700     Preparing to run macOS Installer...

Sep 09 2017 16:40:35 -0700 Saving application inventory...

Sep 09 2017 16:40:44 -0700     System will restart and begin upgrade of macOS.

Sep 09 2017 16:40:55 -0700 ERROR: Unexpected error in munkilib.osinstaller:

Sep 09 2017 16:40:55 -0700 Traceback (most recent call last):

  File "/usr/local/munki/managedsoftwareupdate", line 253, in doInstallTasks

    success = osinstaller.run(finishing_tasks=doFinishingTasks)

  File "/usr/local/munki/munkilib/osinstaller.py", line 483, in run

    finishing_tasks=finishing_tasks, installinfo=item)

  File "/usr/local/munki/munkilib/osinstaller.py", line 432, in startosinstall

    finishing_tasks=finishing_tasks, installinfo=installinfo).start()

  File "/usr/local/munki/munkilib/osinstaller.py", line 316, in start

    time.sleep(1)

  File "/usr/local/munki/managedsoftwareupdate", line 86, in signal_handler

    sys.exit()

SystemExit

That last bit looks scary/worrisome, but is what I expect -- `startosinstall` initiates a restart, which then means a SIGTERM gets sent to every process, including the managedsoftwareupdate process. That gets caught by the signal_handler function registered by managedsoftwareupdate, which logs a traceback (note that it happens while waiting for `startosinstall` to complete, as expected). The OS install then happens, and about 35 minutes later, the machine boots into 10.13, and Munki starts to run again at the loginwindow:

Sep 09 2017 17:15:44 -0700     Waiting for network...

[Eric Holtam]

I have a different result testing from an unencrypted VM running macOS 10.12.1 running munki 3.1.0.3422.

The installer import was not customized at all. I just munkiimported the .app installer, didn't change anything in the pkginfo, added the pkg to a manifest and let the client pick up the update.

Managed Software Center.app displays the available update, click Update All, prompt to log out, log out, the munki status appears for a brief moment and then disappears.  The logs show the following.

    Sep 10 2017 00:46:42 -0500     The following items will be installed or upgraded:

    Sep 10 2017 00:46:42 -0500         + Install_macOS_High_Sierra_Beta-10.13

    Sep 10 2017 00:46:42 -0500             Installs macOS version 10.13

    Sep 10 2017 00:46:42 -0500            *Restart required

    Sep 10 2017 00:46:42 -0500 Finishing...

    Sep 10 2017 00:46:42 -0500 Saving application inventory...

    Sep 10 2017 00:46:47 -0500 ### Ending managedsoftwareupdate run ###

    Sep 10 2017 00:46:57 -0500 ### Starting managedsoftwareupdate run: logoutinstall ###

    Sep 10 2017 00:46:57 -0500 Starting...

    Sep 10 2017 00:46:57 -0500 Skipping Apple Software Updates because items to be installed from the Munki repo contain Apple items.

    Sep 10 2017 00:46:57 -0500     Preventing idle sleep

    Sep 10 2017 00:46:57 -0500 ### Beginning managed installer session ###

    Sep 10 2017 00:46:57 -0500 Processing installs

    Sep 10 2017 00:46:57 -0500 ###    End managed installer session    ###

    Sep 10 2017 00:46:57 -0500     Allowing idle sleep

    Sep 10 2017 00:46:57 -0500 ### Beginning os installer session ###

    Sep 10 2017 00:46:57 -0500 Starting macOS upgrade...

    Sep 10 2017 00:46:57 -0500     Mounting disk image Install macOS High Sierra Beta-10.13.dmg

    Sep 10 2017 00:47:02 -0500     Error: could not find target...

    Sep 10 2017 00:47:02 -0500 WARNING: Polite unmount failed: hdiutil: couldn't unmount "disk2" - Resource busy

    Sep 10 2017 00:47:02 -0500 WARNING: Attempting to force unmount /Volumes/Install macOS High Sierra Beta

    Sep 10 2017 00:47:02 -0500     Starting macOS install failed with return code 5

    Sep 10 2017 00:47:02 -0500 ERROR: ------------------------------------------------------------------------------

    Sep 10 2017 00:47:02 -0500 ERROR: By using the agreetolicense option, you are agreeing that you have run this tool with the license only option and have read and agreed to the terms.

    Sep 10 2017 00:47:02 -0500 ERROR: If you do not agree, press CTRL-C and cancel this process immediately.

    Sep 10 2017 00:47:02 -0500 ERROR: Error: could not find target...

    Sep 10 2017 00:47:02 -0500 ERROR: ------------------------------------------------------------------------------

    Sep 10 2017 00:47:02 -0500 ERROR: Error starting macOS install: startosinstall failed with return code 5

    Sep 10 2017 00:47:02 -0500 ### Ending os installer session ###

    Sep 10 2017 00:47:02 -0500 Finishing...

    Sep 10 2017 00:47:02 -0500 Saving application inventory...

    Sep 10 2017 00:47:05 -0500 ### Ending managedsoftwareupdate run ###

The error "Error: could not find target..." seems to be coming from `startosinstall` itself so I'm not sure what target it isn't able to find.  

-Eric

[Eric Holtam]

Ignore this.  The issue was the VM didn't have enough disk space available.  The disk space issue was found in /var/log/install.log.

After clearing out disk space the OS upgrade install started as expected.

-Eric

[Eric Holtam]

This brings up the question of what is the free disk space requirement of High Sierra.

The pkginfo of the installer states 8.8GB

        <key>installed_size</key>

        <integer>9227469</integer>

My VM had just over 12GB available at the time of the failure.  I removed 5GB to make a total of 17GB free on disk when the install could proceed.

From `/Volumes/InstallESD/Packages/OSInstall.mpkg` the distribution script shows that the size of the included packages is nearly 12GB. 

    <system-image id="com.apple.dmg.MacOSX">BaseSystem.dmg</system-image>

    <pkg-ref id="com.apple.pkg.Core" installKBytes="12332302" version="10.13.0.1.1.1504163811"/>

    <pkg-ref id="com.apple.pkg.FirmwareUpdate" installKBytes="0" version="10.13.0.1"/>

    <pkg-ref id="com.apple.pkg.EmbeddedOSFirmware" installKBytes="62122" version="10.13.0.1.1.1504163811"/>

I don't see any official Apple free space requirements online, only model requirements.

-Eric

[Gregory Neagle]

On Sep 10, 2017, at 7:53 AM, Eric Holtam <eho...@gmail.com> wrote:

Ignore this.  The issue was the VM didn't have enough disk space available.  The disk space issue was found in /var/log/install.log.

Any helpful details there?

--
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.
To post to this group, send email to munk...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Eric Holtam]

Slight correction on the VM disk space. There is 15.03GB available when it is failing.  I remove 5GB and have 20.04GB when the install can proceed.

Here's the pertinent section of the install.log file. I've bolded the section about the free space issue. It looks like it thinks there was only around 9.79 GB available. The Finder was reporting 15GB free and `df` says there's 13GB free...maybe that's the "reclaimable" Finder adjustment in action.

Sep 10 09:43:59 1012 osinstallersetupd[722]: OSISChunkedDownload loaded...

Sep 10 09:43:59 1012 osinstallersetupd[722]: seedingInfoDict ->

Sep 10 09:43:59 1012 osinstallersetupd[722]: result : Success

Sep 10 09:43:59 1012 osinstallersetupd[722]: seedProgramSource : Xattr

Sep 10 09:43:59 1012 osinstallersetupd[722]: seedProgram : DeveloperSeed

Sep 10 09:43:59 1012 osinstallersetupd[722]: catalogURLString : https://swscan.apple.com/content/catalogs/others/index-10.13seed-10.13-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz

Sep 10 09:43:59 1012 osinstallersetupd[722]: fileName : /Volumes/Install macOS High Sierra Beta/Install macOS High Sierra Beta.app

Sep 10 09:43:59 1012 osinstallersetupd[722]: error : No error

Sep 10 09:43:59 1012 osinstallersetupd[722]: OSISSoftwareUpdateController: Using catalog (source: Xattr): https://swscan.apple.com/content/catalogs/others/index-10.13seed-10.13-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz

Sep 10 09:43:59 1012 osinstallersetupd[722]: mountDiskImageWithPath: /Volumes/Install macOS High Sierra Beta/Install macOS High Sierra Beta.app/Contents/SharedSupport/InstallESD.dmg

Sep 10 09:44:00 1012 osinstallersetupd[722]: OSISSoftwareUpdateController: Loaded catalog https://swscan.apple.com/content/catalogs/others/index-10.13seed-10.13-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz (537 products)

Sep 10 09:44:01 1012 osinstallersetupd[722]: Mounting disk image complete, results dict = {

   "system-entities" =     (

               {

           "content-hint" = "GUID_partition_scheme";

           "dev-entry" = "/dev/disk3";

           "potentially-mountable" = 0;

           "unmapped-content-hint" = "GUID_partition_scheme";

       },

               {

           "content-hint" = EFI;

           "dev-entry" = "/dev/disk3s1";

           "potentially-mountable" = 1;

           "unmapped-content-hint" = "C12A7328-F81F-11D2-BA4B-00A0C93EC93B";

           "volume-kind" = msdos;

       },

               {

           "content-hint" = "Apple_HFS";

           "dev-entry" = "/dev/disk3s2";

           "mount-point" = "/Volumes/InstallESD";

           "potentially-mountable" = 1;

           "unmapped-content-hint" = "48465300-0000-11AA-AA11-00306543ECAC";

           "volume-kind" = hfs;

       }

   );

}

Sep 10 09:44:01 1012 osinstallersetupd[722]: Mount point /Volumes/InstallESD

Sep 10 09:44:01 1012 osinstallersetupd[722]: Using product <OSISSharedSupportProduct: 0x7f8969a47580> at distance 10

Sep 10 09:44:01 1012 osinstallersetupd[722]: Using product <OSISInstallMediaProduct> based on media at /Volumes/InstallESD at distance 5

Sep 10 09:44:01 1012 osinstallersetupd[722]: Failed to load BridgeOSInstall.framework: dlopen(/System/Library/PrivateFrameworks/BridgeOSInstall.framework/BridgeOSInstall, 1): image not found

Sep 10 09:44:01 1012 osinstallersetupd[722]: Current version of BridgeOSInstall.framework doesn't have the latest API, assuming machine does not have bridgeOS

Sep 10 09:44:01 1012 osinstallersetupd[722]: osinstallersetupd registered client

Sep 10 09:44:01 1012 osinstallersetupd[722]: Is solid state disk returned: -69808

Sep 10 09:44:01 --- last message repeated 1 time ---

Sep 10 09:44:01 1012 osinstallersetupd[722]: Using product <OSISCollectionInstallProduct: 0x7f89686de9f0> at distance 10

Sep 10 09:44:01 1012 osinstallersetupd[722]: Helper tool loaded

Sep 10 09:44:01 1012 osinstallersetupd[722]: Install was requested to a disk that was not evaluated. Blocking on evaluation.

Sep 10 09:44:01 1012 osinstallersetupd[722]: Specifier (<PKPackageSpecifier>:

{

   URL = "file:///Volumes/InstallESD/Packages/Core.pkg";

   authLevel = 2;

   displayName = macOS;

   identifier = "com.apple.pkg.Core";

   options = 16;

   version = "10.13.0.1.1.1504163811";

}) missing reference.

Sep 10 09:44:01 1012 osinstallersetupd[722]: Specifier (<PKPackageSpecifier>:

{

   URL = "file:///Volumes/InstallESD/Packages/EmbeddedOSFirmware.pkg";

   authLevel = 2;

   displayName = macOS;

   identifier = "com.apple.pkg.EmbeddedOSFirmware";

   options = 16;

   version = "10.13.0.1.1.1504163811";

}) missing reference.

Sep 10 09:44:01 1012 osinstallersetupd[722]: No available package ref for compatibility update. Ignoring.

Sep 10 09:44:01 1012 osinstallersetupd[722]: version = 10.12.1

Sep 10 09:44:01 1012 osinstallersetupd[722]: OSISCustomizationController: Using version 10.12 from InstallSystemSizes.plist

Sep 10 09:44:01 1012 osinstallersetupd[722]: OSISCustomizationController: System size: 10515609460 bytes (***my conversion to GB = 9.793424475938082 GB)

Sep 10 09:44:01 1012 osinstallersetupd[722]: Not enough free space error: Error Domain=com.apple.OSInstallerSetup.error Code=213 "There is not enough free space on the selected volume to upgrade the OS. An additional 2.39 GB is required." UserInfo={NSLocalizedDescription=There is not enough free space on the selected volume to upgrade the OS. An additional 2.39 GB is required.}

Sep 10 09:44:01 1012 osinstallersetupd[722]: The requested target is not valid because: Error Domain=com.apple.OSInstallerSetup.error Code=213 "There is not enough free space on the selected volume to upgrade the OS. An additional 2.39 GB is required." UserInfo={NSLocalizedDescription=There is not enough free space on the selected volume to upgrade the OS. An additional 2.39 GB is required.}

Sep 10 09:44:08 1012 softwareupdate_download_service[234]: Finished downloading package FirmwareUpdate.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_CbPRZt.tmp (error (null)) from peer: (null)

Sep 10 09:44:09 1012 suhelperd[185]: Verifying package at path: /Library/Updates/091-22861/FirmwareUpdate.pkg

Sep 10 09:44:09 1012 softwareupdate_download_service[234]: SUURLSessionDownload task:didCompleteWithError for package FirmwareUpdate.pkg with error (Domain: (null), Code: 0 ((null)))

Sep 10 09:44:13 1012 installd[801]: installd: Starting

Sep 10 09:44:13 1012 installd[801]: installd: uid=0, euid=0

Sep 10 09:44:20 1012 system_installd[350]: PackageKit: found orphaned sandbox with mismatched session UUID - will clean up: /.PKInstallSandboxManager-SystemSoftware/E8451E20-A6AB-4941-8DE0-E50E976C8D76.activeSandbox

Sep 10 09:44:20 1012 system_installd[350]: PackageKit: Found orphaned and possible corrupt sandbox /.PKInstallSandboxManager-SystemSoftware/E8451E20-A6AB-4941-8DE0-E50E976C8D76.activeSandbox with size 105944

Sep 10 09:44:20 1012 system_installd[350]: Purgeable Orphaned Space is: 105944

Sep 10 09:44:20 1012 system_installd[350]: PackageKit: found orphaned sandbox with mismatched session UUID - will clean up: /.PKInstallSandboxManager-SystemSoftware/E8451E20-A6AB-4941-8DE0-E50E976C8D76.activeSandbox

Sep 10 09:44:20 1012 system_installd[350]: PackageKit: Found orphaned and possible corrupt sandbox /.PKInstallSandboxManager-SystemSoftware/E8451E20-A6AB-4941-8DE0-E50E976C8D76.activeSandbox with size 105944

Sep 10 09:44:20 1012 system_installd[350]: Purgeable Orphaned Space is: 105944

Sep 10 09:44:25 1012 softwareupdate_notify_agent[909]: Handling notification event: LoginDone

Sep 10 09:44:25 1012 softwareupdate_notify_agent[909]: AssertionMgr: Take com.apple.softwareupdate.NotifyAgentAssertion-LoginDone assertion with type BackgroundTask for pid 909, id 0x8232

Sep 10 09:44:25 1012 softwareupdated[181]: Adding client SUUpdateServiceClient pid=909, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_notify_agent)

Sep 10 09:44:25 1012 softwareupdate_notify_agent[909]: Notifying with params: {

   UpdateNotificationsOnly = 1;

}

Sep 10 09:44:25 1012 softwareupdate_notify_agent[909]: appstoreupdateagent notified

Sep 10 09:44:25 1012 softwareupdate_notify_agent[909]: AssertionMgr: Cancel com.apple.softwareupdate.NotifyAgentAssertion-LoginDone assertion for pid 909, id 0x8232

Sep 10 09:44:25 1012 softwareupdated[181]: Adding client SUUpdateServiceClient pid=817, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/PrivateFrameworks/CommerceKit.framework/Versions/A/Resources/storeassetd)

Sep 10 09:44:25 1012 storeassetd[817]: Query for available updates: FINISHED

-Eric

[Eric Holtam]

This line from the install.log may show where it's pulling the free space threshold value from.

`Sep 10 09:44:01 1012 osinstallersetupd[722]: OSISCustomizationController: Using version 10.12 from InstallSystemSizes.plist`

Know where that file is being referenced from? I've not seen it before.

-Eric

[Eric Holtam]

Found it here:

/Volumes/OS X Base System/Install macOS High Sierra Beta.app/Contents/Frameworks/OSInstallerSetup.framework/Versions/A/Frameworks/OSInstallerSetupInternal.framework/Versions/A/Resources/InstalledSystemSizes.plist

Contents:

<?xml version="1.0" encoding="UTF-8"?>

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

<plist version="1.0">

<dict>

<key>10.10</key>

<integer>6797570048</integer>

<key>10.10.1</key>

<integer>7036334080</integer>

<key>10.11</key>

<integer>11697816775</integer>

<key>10.12</key>

<integer>10515609460</integer>

<key>10.13</key>

<integer>10596806656</integer>

<key>10.6.8</key>

<integer>4103753728</integer>

<key>10.6.8_Server</key>

<integer>7416717796</integer>

<key>10.7.5</key>

<integer>5286875136</integer>

<key>10.8.5</key>

<integer>5245394944</integer>

<key>10.9</key>

<integer>6135296000</integer>

<key>10.9.1</key>

<integer>6134992896</integer>

<key>10.9.2</key>

<integer>6617333760</integer>

<key>10.9.3</key>

<integer>6870405120</integer>

<key>10.9.4</key>

<integer>6230339584</integer>

<key>10.9.5</key>

<integer>6252519424</integer>

</dict>

</plist>

Not sure if that's helpful or not. I would guess the values are in bytes.  The log stated it was using 10.12's value of 10515609460 or  9.793424475938082 GB.

-Eric

[Gregory Neagle]

Also at "/Applications/Install macOS High Sierra Beta.app/Contents/Frameworks/OSInstallerSetup.framework/Versions/A/Frameworks/OSInstallerSetupInternal.framework/Versions/A/Resources/InstalledSystemSizes.plist"

But it's unclear what it _means_ -- are we to believe that if we are upgrading from 10.8.5 we only need a little over 5G free, but if we are upgrading from 10.12, we need over 10G free? That seems counter-intuitive.

I'd really like to see _all_ of the install.log from the install attempt.

-Greg

[Eric Holtam]

The complete contents of install.log during an install attempt:

Sep 10 13:52:58 1012 softwareupdated[201]: Removing client SUUpdateServiceClient pid=451, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/PrivateFrameworks/CommerceKit.framework/Versions/A/Resources/storeassetd)

Sep 10 13:53:00 1012 osinstallersetupd[694]: OSISChunkedDownload loaded...

Sep 10 13:53:00 1012 osinstallersetupd[694]: seedingInfoDict ->

Sep 10 13:53:00 1012 osinstallersetupd[694]: result : Success

Sep 10 13:53:00 1012 osinstallersetupd[694]: seedProgramSource : Xattr

Sep 10 13:53:00 1012 osinstallersetupd[694]: seedProgram : DeveloperSeed

Sep 10 13:53:00 1012 osinstallersetupd[694]: catalogURLString : https://swscan.apple.com/content/catalogs/others/index-10.13seed-10.13-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz

Sep 10 13:53:00 1012 osinstallersetupd[694]: fileName : /Volumes/Install macOS High Sierra Beta/Install macOS High Sierra Beta.app

Sep 10 13:53:00 1012 osinstallersetupd[694]: error : No error

Sep 10 13:53:00 1012 osinstallersetupd[694]: OSISSoftwareUpdateController: Using catalog (source: Xattr): https://swscan.apple.com/content/catalogs/others/index-10.13seed-10.13-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz

Sep 10 13:53:00 1012 osinstallersetupd[694]: mountDiskImageWithPath: /Volumes/Install macOS High Sierra Beta/Install macOS High Sierra Beta.app/Contents/SharedSupport/InstallESD.dmg

Sep 10 13:53:01 1012 osinstallersetupd[694]: OSISSoftwareUpdateController: Loaded catalog https://swscan.apple.com/content/catalogs/others/index-10.13seed-10.13-10.12-10.11-10.10-10.9-mountainlion-lion-snowleopard-leopard.merged-1.sucatalog.gz (537 products)

Sep 10 13:53:02 1012 osinstallersetupd[694]: Mounting disk image complete, results dict = {

   "system-entities" =     (

               {

           "content-hint" = "GUID_partition_scheme";

           "dev-entry" = "/dev/disk3";

           "potentially-mountable" = 0;

           "unmapped-content-hint" = "GUID_partition_scheme";

       },

               {

           "content-hint" = EFI;

           "dev-entry" = "/dev/disk3s1";

           "potentially-mountable" = 1;

           "unmapped-content-hint" = "C12A7328-F81F-11D2-BA4B-00A0C93EC93B";

           "volume-kind" = msdos;

       },

               {

           "content-hint" = "Apple_HFS";

           "dev-entry" = "/dev/disk3s2";

           "mount-point" = "/Volumes/InstallESD";

           "potentially-mountable" = 1;

           "unmapped-content-hint" = "48465300-0000-11AA-AA11-00306543ECAC";

           "volume-kind" = hfs;

       }

   );

}

Sep 10 13:53:02 1012 osinstallersetupd[694]: Mount point /Volumes/InstallESD

Sep 10 13:53:02 1012 osinstallersetupd[694]: Using product <OSISSharedSupportProduct: 0x7f8ceaf9f020> at distance 10

Sep 10 13:53:02 1012 osinstallersetupd[694]: Using product <OSISInstallMediaProduct> based on media at /Volumes/InstallESD at distance 5

Sep 10 13:53:02 1012 osinstallersetupd[694]: Failed to load BridgeOSInstall.framework: dlopen(/System/Library/PrivateFrameworks/BridgeOSInstall.framework/BridgeOSInstall, 1): image not found

Sep 10 13:53:02 1012 osinstallersetupd[694]: Current version of BridgeOSInstall.framework doesn't have the latest API, assuming machine does not have bridgeOS

Sep 10 13:53:02 1012 osinstallersetupd[694]: osinstallersetupd registered client

Sep 10 13:53:02 1012 osinstallersetupd[694]: Is solid state disk returned: -69808

Sep 10 13:53:02 --- last message repeated 1 time ---

Sep 10 13:53:02 1012 osinstallersetupd[694]: Using product <OSISCollectionInstallProduct: 0x7f8cec1868a0> at distance 10

Sep 10 13:53:02 1012 osinstallersetupd[694]: Helper tool loaded

Sep 10 13:53:02 1012 osinstallersetupd[694]: Install was requested to a disk that was not evaluated. Blocking on evaluation.

Sep 10 13:53:02 1012 osinstallersetupd[694]: Specifier (<PKPackageSpecifier>:

{

   URL = "file:///Volumes/InstallESD/Packages/Core.pkg";

   authLevel = 2;

   displayName = macOS;

   identifier = "com.apple.pkg.Core";

   options = 16;

   version = "10.13.0.1.1.1504163811";

}) missing reference.

Sep 10 13:53:02 1012 osinstallersetupd[694]: Specifier (<PKPackageSpecifier>:

{

   URL = "file:///Volumes/InstallESD/Packages/EmbeddedOSFirmware.pkg";

   authLevel = 2;

   displayName = macOS;

   identifier = "com.apple.pkg.EmbeddedOSFirmware";

   options = 16;

   version = "10.13.0.1.1.1504163811";

}) missing reference.

Sep 10 13:53:02 1012 osinstallersetupd[694]: No available package ref for compatibility update. Ignoring.

Sep 10 13:53:02 1012 osinstallersetupd[694]: version = 10.12.1

Sep 10 13:53:02 1012 osinstallersetupd[694]: OSISCustomizationController: Using version 10.12 from InstallSystemSizes.plist

Sep 10 13:53:02 1012 osinstallersetupd[694]: OSISCustomizationController: System size: 10515609460 bytes

Sep 10 13:53:02 1012 osinstallersetupd[694]: Not enough free space error: Error Domain=com.apple.OSInstallerSetup.error Code=213 "There is not enough free space on the selected volume to upgrade the OS. An additional 3.2 GB is required." UserInfo={NSLocalizedDescription=There is not enough free space on the selected volume to upgrade the OS. An additional 3.2 GB is required.}

Sep 10 13:53:02 1012 osinstallersetupd[694]: The requested target is not valid because: Error Domain=com.apple.OSInstallerSetup.error Code=213 "There is not enough free space on the selected volume to upgrade the OS. An additional 3.2 GB is required." UserInfo={NSLocalizedDescription=There is not enough free space on the selected volume to upgrade the OS. An additional 3.2 GB is required.}

Sep 10 13:53:13 1012 installd[767]: installd: Starting

Sep 10 13:53:13 1012 installd[767]: installd: uid=0, euid=0

Sep 10 13:53:27 1012 softwareupdate_notify_agent[857]: Handling notification event: LoginDone

Sep 10 13:53:27 1012 softwareupdate_notify_agent[857]: AssertionMgr: Take com.apple.softwareupdate.NotifyAgentAssertion-LoginDone assertion with type BackgroundTask for pid 857, id 0x8259

Sep 10 13:53:27 1012 softwareupdated[201]: Adding client SUUpdateServiceClient pid=857, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdate_notify_agent)

Sep 10 13:53:27 1012 softwareupdate_notify_agent[857]: Notifying with params: {

   UpdateNotificationsOnly = 1;

}

Sep 10 13:53:27 1012 softwareupdate_notify_agent[857]: appstoreupdateagent notified

Sep 10 13:53:27 1012 softwareupdate_notify_agent[857]: AssertionMgr: Cancel com.apple.softwareupdate.NotifyAgentAssertion-LoginDone assertion for pid 857, id 0x8259

Sep 10 13:53:27 1012 softwareupdated[201]: Adding client SUUpdateServiceClient pid=779, uid=501, installAuth=NO rights=(), transactions=0 (/System/Library/PrivateFrameworks/CommerceKit.framework/Versions/A/Resources/storeassetd)

Sep 10 13:53:28 1012 storeassetd[779]: Query for available updates: FINISHED

Sep 10 13:53:38 1012 system_installd[372]: PackageKit: found orphaned sandbox with mismatched session UUID - will clean up: /.PKInstallSandboxManager-SystemSoftware/E8451E20-A6AB-4941-8DE0-E50E976C8D76.activeSandbox

Sep 10 13:53:38 1012 system_installd[372]: PackageKit: Trashing orphaned and possibly corrupt sandbox /.PKInstallSandboxManager-SystemSoftware/E8451E20-A6AB-4941-8DE0-E50E976C8D76.activeSandbox with size 105944

Sep 10 13:53:50 1012 softwareupdate_download_service[297]: Finished downloading package macOSUpdCombo10.12.6Auto.pkg to file:///var/folders/zz/zyxvpxvq6csfxvn_n00000s0000068/C/com.apple.SoftwareUpdate/CFNetworkDownload_BMUAml.tmp (error (null)) from peer: (null)

Sep 10 13:54:00 1012 suhelperd[206]: Verifying package at path: /Library/Updates/091-22861/macOSUpdCombo10.12.6Auto.pkg

Sep 10 13:54:01 1012 softwareupdate_download_service[297]: SUURLSessionDownload task:didCompleteWithError for package macOSUpdCombo10.12.6Auto.pkg with error (Domain: (null), Code: 0 ((null)))

Sep 10 13:54:01 1012 softwareupdate_download_service[297]: No more tasks for com.apple.SoftwareUpdate.DownloadService.091-22861:1 - invalidating session now

Sep 10 13:54:01 1012 softwareupdate_download_service[297]: Finished download of 091-22861

Sep 10 13:54:01 1012 softwareupdated[201]: The download service has finished with product <SUProduct: 091-22861>

Sep 10 13:54:01 1012 softwareupdated[201]: Finished downloading 5 products

Sep 10 13:54:14 1012 system_installd[372]: PackageKit: prevent user idle system sleep

Sep 10 13:54:14 1012 system_installd[372]: PackageKit: suspending backupd

Sep 10 13:54:14 1012 system_installd[372]: PackageKit: Using system content trashcan path /.PKInstallSandboxManager-SystemSoftware/608AF018-C2E5-4633-B4CB-EF49400D979A.activeSandbox/Trashes for sandbox /.PKInstallSandboxManager-SystemSoftware/608AF018-C2E5-4633-B4CB-EF49400D979A.activeSandbox

Sep 10 13:54:14 1012 system_installd[372]: PackageKit: Shoving /.PKInstallSandboxManager-SystemSoftware/608AF018-C2E5-4633-B4CB-EF49400D979A.activeSandbox/Root (2 items) to /

Sep 10 13:54:15 1012 install_monitor[877]: Temporarily excluding: /Applications, /Library, /System, /bin, /private, /sbin, /usr

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: Writing system content receipt for com.apple.pkg.XProtectPlistConfigData.16U4011 to /

Sep 10 13:54:15 1012 system_installd[372]: Installed "XProtectPlistConfigData" (1.0)

Sep 10 13:54:15 1012 install_monitor[877]: Re-included: /Applications, /Library, /System, /bin, /private, /sbin, /usr

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: releasing backupd

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: allow user idle system sleep

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: ----- End install -----

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: 190.6s elapsed install time

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: Running idle tasks

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: Done with sandbox removals

Sep 10 13:54:15 1012 system_installd[372]: PackageKit: Removing client PKInstallDaemonClient pid=201, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Sep 10 13:54:16 --- last message repeated 1 time ---

Sep 10 13:54:16 1012 softwareupdated[201]: Changing status (_installProducts) for key 091-25423 from "installing" to "installed"

Sep 10 13:54:16 1012 softwareupdated[201]: SoftwareUpdate: finished install of 091-25423

Sep 10 13:54:16 1012 softwareupdated[201]: Removing 091-25423

Sep 10 13:54:16 1012 softwareupdated[201]: Removed local product for 091-25423 (1)

Sep 10 13:54:16 1012 softwareupdated[201]: Stopping transaction with ID [0x1]

Sep 10 13:54:16 1012 softwareupdated[201]: SoftwareUpdate: Removed background transaction [0x1]

Sep 10 13:54:16 1012 softwareupdated[201]: Removing client SUUpdateServiceClient pid=473, uid=200, installAuth=YES rights=(system.install.apple-config-data), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/SoftwareUpdateConfigData)

Sep 10 13:54:16 1012 softwareupdated[201]: Install status changed externally for product: 091-30880

Sep 10 13:54:16 1012 softwareupdate_notify_agent[857]: Handling notification event: UpdatesAvailable

Sep 10 13:54:16 1012 softwareupdate_notify_agent[857]: AssertionMgr: Take com.apple.softwareupdate.NotifyAgentAssertion-UpdatesAvailable assertion with type BackgroundTask for pid 857, id 0x8274

Sep 10 13:54:16 1012 softwareupdate_notify_agent[857]: Waiting 60 seconds before sending the notification to App Store

Sep 10 13:54:16 1012 softwareupdated[201]: Changing status (updateStatusChangedExternally) for key 091-30880 from "not running" to "downloaded"

Sep 10 13:54:16 1012 softwareupdated[201]: Adding client SUUpdateServiceClient pid=882, uid=200, installAuth=NO rights=(), transactions=0 (/System/Library/CoreServices/Software Update.app/Contents/Resources/SoftwareUpdateConfigData)

Sep 10 13:54:17 1012 softwareupdated[201]: Running session-idle tasks.

Sep 10 13:54:17 1012 softwareupdated[201]: Checking for inapplicable local products remaining on disk for cleanup

Sep 10 13:54:17 1012 softwareupdated[201]: The following local product is no longer applicable and will be removed: zzzz091-04062

Sep 10 13:54:17 1012 softwareupdated[201]: Removed local product for zzzz091-04062 (1)

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: Adding client PKInstallDaemonClient pid=201, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Sep 10 13:54:18 1012 softwareupdated[201]: SUUpdateSession startUpdateForProducts:<SUProduct: 091-30880> inForeground: NO stageOnly: NO preLogoutCommit: NO

Sep 10 13:54:18 1012 softwareupdated[201]: SoftwareUpdate: Added background transaction [0x2] for MRTConfigData-1.0

Sep 10 13:54:18 1012 softwareupdated[201]: Changing status (_installProducts) for key 091-30880 from "downloaded" to "waiting to install"

Sep 10 13:54:18 1012 softwareupdated[201]: Changing status (_installProducts) for key 091-30880 from "waiting to install" to "installing"

Sep 10 13:54:18 1012 softwareupdated[201]: Package Authoring Error: PackageInfo bundle reference found without top-level bundle definition. Bundle will be skipped: <bundle id="*"></bundle>

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: Adding client PKInstallDaemonClient pid=201, uid=200 (/System/Library/CoreServices/Software Update.app/Contents/Resources/softwareupdated)

Sep 10 13:54:18 1012 softwareupdated[201]: PackageKit: Enqueuing install with default quality of service (background)

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: ----- Begin install -----

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: request=PKInstallRequest <1 packages, destination=/>

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: packages=(

   "PKLeopardPackage <file:///Library/Updates/091-30880/MRTConfigData.pkg>"

)

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: Session UUID file exists - will not overwrite /.PKInstallSandboxManager-SystemSoftware/EBC68F4C-00FB-449E-B7FD-BC5052F38BA8.activeSandbox

Sep 10 13:54:18 1012 system_installd[372]: Package Authoring Error: PackageInfo bundle reference found without top-level bundle definition. Bundle will be skipped: <bundle id="*"></bundle>

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: Extracting file:///Library/Updates/091-30880/MRTConfigData.pkg (destination=/.PKInstallSandboxManager-SystemSoftware/EBC68F4C-00FB-449E-B7FD-BC5052F38BA8.activeSandbox/Root, uid=0)

Sep 10 13:54:18 1012 system_installd[372]: PackageKit: update_dyld_shared_cache -overlay /.PKInstallSandboxManager-SystemSoftware/EBC68F4C-00FB-449E-B7FD-BC5052F38BA8.activeSandbox/Root

[Ben Goodstein]

> On 10 Sep 2017, at 01:24, Gregory Neagle <gregn...@mac.com> wrote:
>
>> Just tried a 10.12.6->10.13 upgrade with Munki 3.1.0.3422 on a VMware Fusion VM (no FileVault) and it proceeded as expected: logout, setup of macOS install, reboot, install of High Sierra beta. The install still has 20+ to go, so I'll examine the ManagedSoftwareUpdate.log after it completes.

OK, my testing may have been compromised both by the way I imported the Install macOS app (in a dmg of my own creation) and by the way I was serving it (using a file:/// URL to a repo on the same VM).

I now cannot recreate the error I was having with an .app imported directly into a munki repo and served over http from the host OS.

So - the upshot of my testing is that the new functionality works to upgrade a FileVault encrypted 10.12 VM to 10.13, correctly disabling fde autologin after a 10.13 upgrade and then bootstrapping at the login window. On subsequent reboots fde autologin is enabled (and bootstrap file is gone from /Users/Shared). This is all without leveraging authrestarts.

Sorry for any confusion!

Ben