The Installer Log Says What?

I recently learned of a hidden capability of the Apple Installer application, namely the ability to display the installation log in real-time. While the Installer is running, choose Window –> Installer Log or type Command-L (aka Apple-L). If you then choose “Show Errors & All Progress” from the log window’s popup menu, you’ll be able to view what’s happening while the wait cursor spins.

I suppose this isn’t so much hidden as unpublicized, but few people seem aware of this capability. During long installations such as Mac OS X installs or upgrades, it helps to see the log being updated to know that your computer is actually still doing something and hasn’t crashed.

During a recent Leopard upgrade – hmmm, is this now a Vintage Mac OS? – I enabled the log viewer and noticed a few odd things scrolling by. I decided to save the log when installation was complete, and parsed out some interesting lines after the fact:
Oct 15 18:12:16 localhost LCA[65]: Launching the Installer using language code “English”

The start of the process

Oct 15 18:12:41 localhost OSInstaller[155]: CPSGetProcessInfo(): This call is deprecated and should not be called anymore.
Oct 15 18:12:41 localhost OSInstaller[155]: CPSPBGetProcessInfo(): This call is deprecated and should not be called anymore.

If these calls are deprecated, why is the Apple Installer still calling them?

Oct 15 18:15:26 localhost OSInstaller[155]: Processing BaseSystem:
Oct 15 18:15:26 localhost OSInstaller[155]: Determining files to install
Oct 15 18:15:27 localhost OSInstaller[155]: It took 1.34 seconds to create the install plan for BaseSystem.
Oct 15 18:15:27 localhost OSInstaller[155]: Configuring deferred files

Much faster than I could create the install plan, that’s for sure; what happens to the deferred files?

Oct 15 18:44:36 localhost root[721]: Begin script: RemoveClientLicense.sh
Oct 15 18:44:36 localhost root[723]: End script: RemoveClientLicense.sh

Interesting; Mac OS X Server is licensed. Perhaps the “honor system” policy Apple uses with Mac OS X Client may not always be so trusting?

Oct 15 18:46:41 localhost OSInstaller[155]: **** Summary Information ****
Oct 15 18:46:41 localhost OSInstaller[155]: Operation Elapsed time
Oct 15 18:46:41 localhost OSInstaller[155]: script 210.33 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: zero 0.03 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: install 1849.14 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: validate 761.56 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: os 2.23 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: extract 829.08 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: receipt 3.65 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: disk 25.50 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: config 44.41 seconds
Oct 15 18:46:41 localhost OSInstaller[155]: Finalizing installation.

Hmmm, this elapsed time totals out to 3725.93 seconds, or 62.1 minutes. According to the log entries, actual elapsed time is about 34.5 minutes. No wonder those “remaining time” calculations are always so far off…

Oct 15 18:46:56 localhost OSInstaller[155]: installAutoFSMonitor: open failed

The final word in the OS X install log is failed. That doesn’t inspire confidence. Perhaps it’s the Revenge of the Deferred Files!