How to check what is preventing MBP from graceful shutdown/restart and fix it? [Now with log entries]

Question

And hopefully really final edit: After upgrading to Mountain Lion, the issue seems fixed, hopefully permanently.

Final Edit: The problem doesn't happen all the time, sometimes I have to wait several days for it to occur. So it is hard to test under different conditions (i.e. safe mode or with some software disabled) and I've decided that it is not worth spending days truing different conditions in order to on fix this. Graham Perrin's suggestions were the most helpful for finding specific information about restart/reboot issues, not found in the general-purpose logs.

Some log entries are in Edit at the bottom:

Mid-2010 15in MacBook Pro, running OS X 10.7.4. Sometimes when trying to restart or shutdown the machine, it won't work -- the screen turns gray, the spinning wheel shows, but the machine doesn't power down so after several minutes I have to shut down the machine by pressing the power button.

It doesn't happen every time, and I can't relate any software used during the session with the problem. In fact, when testing this, sometimes this would happen when I try to shutdown the machine immediately after starting it.

How to check what is preventing the graceful shutdown/restart? I assume that I have to look in some log files, but I am not sure which ones and what to look for.

Edit: Added the verbose start/shutdown setting in the nvram as suggested by Graham Perrin, and eventually the machine got stuck on reboot. I saw some verbose entries on the screen and after rebooting found them in in /var/log/launchd-shutdown.log. It appears that WindowServer may have something to do with it. Below is the end of that log file with the first 3 columns removed (the first had some increasing integer numbers, the second had entries of "1" and the third -- "com.apple.launchd"):

234 com.apple.WindowServer   Dispatching kevent callback.
234 com.apple.WindowServer   Job has not died after being killed 2 seconds ago. Simulating exit.
234 com.apple.WindowServer   Dispatching kevent callback.
234 com.apple.WindowServer   EVFILT_PROC event for job.
1 com.apple.launchd         KEVENT[0]: udata = 0x107827a90 data = 0x0 ident = 234 filter = EVFILT_PROC flags= 0x0 fflags = NOTE_EXIT
234 com.apple.WindowServer   Reaping
234 com.apple.WindowServer   Simulated exit: <rdar://problem/9359725>
234 com.apple.WindowServer   Exited 22.016701 seconds after the first signal was sent
0 com.apple.WindowServer     Exited while shutdown in progress. Processes remaining: 0/0
0 com.apple.WindowServer   Job was last to exit during shutdown of: System.
0 com.apple.WindowServer    Total rusage: utime 0.000000 stime 0.000000 maxrss 0 ixrss 0 idrss 0 isrss 0 minflt 0 majflt 0 nswap 0 inblock 0 oublock 0 msgsnd 0 msgrcv 0 nsignals 0 nvcsw 0 nivcsw 0
0 com.apple.WindowServer  Closing receive right for com.apple.windowserver.active
0 com.apple.WindowServer  Mach service deleted: com.apple.windowserver.active
0 com.apple.WindowServer  Closing receive right for com.apple.windowserver
0 com.apple.WindowServer   Mach service deleted: com.apple.windowserver
0 com.apple.WindowServer    Removed
1 com.apple.launchd      System: No submanagers left.
1 com.apple.launchd    System: Removing.
1 com.apple.launchd   System: Removing job manager.
1 com.apple.launchd    System: Userspace shutdown finished at: Wed Aug  1 08:53:12 2012
1 com.apple.launchd   System: Userspace shutdown took approximately 22 seconds.
1 com.apple.launchd   VM statistics (now - orig): Free: 28472 Active: -21833 Inactive: -1038 Reactivations: 0 PageIns: 25 PageOuts: 0 Faults: 1654 COW-Faults: 335 Purgeable: -849 Purges: 0
1 com.apple.launchd   System: Stray process at shutdown: PID 234 PPID 1 PGID 234 WindowServer
1 com.apple.launchd       System: About to call: reboot(RB_HALT).

Answer 1

Complementing other answers …

---

Observe verbose mode during restart or shut down

Mac OS X: How to start up in single-user or verbose mode

– if you start in verbose mode, then restart or shut down will be similarly verbose.

Hint: if things in verbose mode seem to not progress beyond a certain point, allow maybe five minutes before either:

• forcing a restart (Command-Control-power); or
• forcing a shutdown (press and hold the power key).

If a forced restart does not succeed, that could be another clue to the cause of the problem(s).

A related question, albeit not problem-oriented: Can anyone interpret verbose shutdown messages?

The problem-oriented case here should be easier to resolve for lupincho. Fewer tea leaves.

To start in verbose mode without keying Command-V

A preference can be stored in NVRAM. Enter the following command in Terminal, and be prepared to enter your admin password:

sudo nvram boot-args="-v"

The next start of the system will be verbose.

---

sysdiagnose

Before each restart or shutdown, in Terminal:

sudo sysdiagnose

It's time consuming, but you need not investigate the results of all runs. Pay attention only if a problems arises.

For a case such as lupincho's:

• the run of sysdiagnose may reveal a problem before a restart or shut down
• the end result of sysdiagnose may be of interest following a forced restart or shut down.

More specifically: if a run of sysdiagnose fails to progress beyond a certain point, knowing that point can help to gain a sense of the underlying problem.

During the run you can use the following key combination, repeatedly, to see whether things are progressing:

• Control-T

For the allmemory part of the sysdiagnose routine, Apple's two minute estimate may be wildly inaccurate. Be patient.

If you suspect that sysdiagnose fails to progress beyond a certain point, then key:

• Control-C

If repeated use of Control-C fails to abort sysdiagnose, then (in my experience with Mountain Lion) it's almost certain that an attempt to restart or shut down the operating system will fail.

---

Shutdown monitoring

In Finder, go to:

/private/var/log/shutdown_monitor.log

This file is typically empty, but may contain items of interest following a problematic shutdown. (I have little experience in this area.)

If the only stray process at shutdown is WindowServer

It's not unusual to have stray processes at shutdown. A stray can be problematic only if it is not killed.

If you suspect that WindowServer is not killed, and that this particular stray is contributory to shutdown failure: ask yourself whether any third party software makes nonstandard use of the WindowServer process.

Quick Look of a GrabFS view of WindowServer on Mountain Lion, with two displays:

If Lion is similar, then my gut feeling is that the cause of shutdown failures lies beyond WindowServer.

---

Guesswork, based upon results of launchctl

Whilst the machine is running normally, what response to the following command?

sudo launchctl list | grep  --invert-match com.apple

Wonder whether any non-Apple software is contributory to the problem. Anti-virus, anti-malware software?

---

Following an upgrade from Lion to Mountain Lion

Aim for:

/private/var/log/com.apple.launchd/launchd-shutdown.system.log

It seems the default is one log per shut down, with a maximum of two so there's also:

/private/var/log/com.apple.launchd/launchd-shutdown.system.log.1

Following any forced restart or forced shut down, you might choose to set aside a copy of the most recent of the two. If force is required on any more than one occasion, you can compare files to see whether a pattern emerges.

Generally

Don't rule out the possibility of an issue with third party software, even release quality. Little Snitch may be well written and widely respected but:

• when problems such as the one in this question become extended or too puzzling, any non-Apple kernel extension deserves attention.

I tested Build 12A269 of OS X 10.8 for around two weeks before it was released, with particular attention to shut down behaviours in difficult situations. Whilst I have not watched any videos from WWDC 2012, I do have a sense that Apple has worked very hard to prevent the need for force in all but the most difficult situations.

Building upon David DelMonte's answer

At least on Mountain Lion, I see the load of Little Snitch 3.0 Preview 2 (3857) very early – before shutdown logging begins. If things relating to this KEXT are similarly late around shutdown time, then maybe an issue will be not evident in the usual log files on disk.

---

If ever you discover the cause of the problem – with either Lion or Mountain Lion – I'll be pleased to know.

In the meantime, with big thanks for the bounty, a closing thought:

kextstat -l | grep --invert-match com.apple

Answer 2

Go to Applications -> Utilities, and open Console

Take a look at the system.log file, you might be able to find something there.

Answer 3

pmset -g assertions gets a summary of power assertions:

$ pmset -g assertions
Assertion status system-wide:
   PreventUserIdleDisplaySleep             0
   CPUBoundAssertion                       0
   DisableInflow                           0
   ChargeInhibit                           0
   PreventSystemSleep                      0
   PreventUserIdleSystemSleep              1
   ExternalMedia                           1
   DisableLowPowerBatteryWarnings          0
   EnableIdleSleep                         1
   NoRealPowerSources_debug                0
   UserIsActive                            0
   ApplePushServiceTask                    0

Listed by owning process:
  pid 153: [0x00000099012c023b] PreventUserIdleSystemSleep named: "com.apple.audio.'AppleUSBAudioEngine:Apple Inc.:Display Audio:15261930:2,1'.noidlesleep" 
  pid 19: [0x00000013012c0235] ExternalMedia named: "com.apple.powermanagement.externalmediamounted" 

You can see the path of a process with ps up $pid:

$ ps up 153
USER          PID  %CPU %MEM      VSZ    RSS   TT  STAT STARTED      TIME COMMAND
_coreaudiod   153   0.0  0.2  2475000   6740   ??  Ss   Fri05PM  12:17.71 /usr/sbin/coreaudiod

Answer 4

I've used to have this problem and did find a fix that worked for me. Although I'm not directly answering your question (how to check what's causing the problem), it's a fix that might be worth a shot:

1. Navigate to "Macintosh HD > Library"
2. Delete the folder named "Java"
3. Empty Trash
4. Shut down
5. Once you run anything Java-related, you will be prompted to reinstall Java, do that.

After that, shutdown time should improve. Note: I'm still getting slow shutdowns when I shutdown immediately after the system starts, so after you follow the steps and want to test, wait a few minutes after the system starts before shutting down.

Answer 5

1. Do you have any peripheral equipment connected (USB, FW, etc)?

If so, it would be interesting to disconnect everything and see if the problem exists.

1. Have you tried repairing permissions, and checking file integrity?

Hope these help.

Answer 6

Some more ideas:

1. Create another user account. Log in only as this test account. If you don't have the problem, it's likely to be something in your user software. If you do have the problem, it's possible it could be hardware.

2. Try to recreate the problem just using battery power.

3. Follow the steps for Apple's System Management controller -

Resetting the System Management Controller (SMC) Resetting the SMC on Mac portables with a battery you can remove

Shut down the computer. Disconnect the MagSafe power adapter from the computer, if it's connected. Remove the battery. Press and hold the power button for 5 seconds. Release the power button. Reconnect the battery and MagSafe power adapter. Press the power button to turn on the computer.

Answer 7

I didn't realize you had Little Snitch running. I just solved a similar issue for a friend, by removing LS. I suggest you try that. To remove properly, download the LS installer again. Run the installer, but select uninstall.

I'm curious too why you would want to use this app..

Answer 8

My girlfriend had merely deleted the directories for parallels by dragging and dropping the dir to the trash can and emptying trash. However, I found parallels again within the Library folder, and there was a shell script (.sh file) to uninstall it properly. This worked and solved our long boot problems.

I mention this because parallels is a known cause of many slow boots and it appears it's not as easy to uninstall as their website indicates (just dragging and dropping the dir).

Happy trails, hope this helps somebody.