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

macosrestartshutdown

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).

Best Answer

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:

enter image description here

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