Waking your Mac from sleep: log highlights

In macOS Sierra, problems waking from sleep have not gone away. They seem to be much less common than in El Capitan, but when they occur they are generally much harder to diagnose, as you are unable to browse past log entries using Console.

I have been looking at some log excerpts using Consolation (see the Downloads item in the above menus if you do not have a copy yet), and offer some milestones which may help guide you through diagnosis of startup problems in Sierra. In each log entry, I give just the timestamp in seconds and details of that entry, for the sake of being concise. If you want full log extracts, just ask.

It’s worth noting here that Apple considers that studying Sierra’s log to investigate sleep and wake problems is incorrect. It recommends instead using the command
pmset -g log
to view a history of wakes, sleeps, and relevant matters. This will normally result in copious output, so it’s probably best to pipe the standard output into a text file:
touch pmsetlogout.text
pmset -g log > pmsetlogout.text

The first sign that you should see of waking from sleep is the kernel entry:
19.000023 kernel: PMRD: System Wake
However, as we’ll see shortly, there are some entries with earlier timestamps which normally appear later in the log, presumably because the logging system is initially shut down, and those entries cannot appear until after the first few steps in waking up. If you’re looking for the start of wake events, filtering on
processImagePath CONTAINS[c] kernel
AND
eventMessage CONTAINS[c] system wake

should return a list of the start of all such events.

During system sleep, the system may wake itself up periodically to perform Time Machine backups and other high-priority tasks, if Power Nap is enabled, but user events scheduled to take place via launchd are normally skipped. So if you have my tool Blowhole writing to the log every hour, those entries will normally cease during sleep.

After that initial announcement from the kernel, there is a short series of further kernel messages:
19.000112 kernel: IOConsoleUsers: gIOScreenLockState 2, hs 0, bs 0, now 1488109939, sm 0xe0000300
19.002616 kernel: (AppleRTC) RTC: PowerByCalendarDate setting ignored
19.002617 kernel: (AppleRTC) RTC: PowerByCalendarDate setting ignored

Normally, Grand Central Dispatch then cuts in:
19.001619 coreduetd: [com.apple.coreduet.admissionCheck.] modulation timer has tickled ***
19.001621 coreduetd: [com.apple.coreduet.admissionCheck.] enough time has passed move slot 68 -> 69

Following that is a long series of back-timed entries as coreduetd gets to work:
18.238974 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1073741825 (variant com.apple.coreduet.budget.energy, type 0, with dailyval 0) to 18 from 18
18.238980 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1073741827 (variant com.apple.coreduet.budget.network, type 0, with dailyval 13000000) to 8184696 from 8066905
18.238989 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1073741828 (variant com.apple.coreduet.budget.network, type 0, with dailyval 100000000) to 62900142 from 61994051
18.239014 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 1 (variant com.apple.coreduet.budget.energy, type 2, with dailyval 0) to 18 from 18
18.239018 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 2 (variant com.apple.coreduet.budget.network, type 2, with dailyval 100000000) to 62959378 from 62053287

running up to the last pool:
19.004567 coreduetd: [com.apple.coreduet.admissionCheck.] Modulating pool 150 (variant com.apple.coreduet.budget.network, type 2, with dailyval 100000000) to 62959378 from 62053287

The kernel then makes its last entry for a while, revealing the reason for the period of sleep:
19.006041 kernel: (AppleSMC) Previous sleep cause: 5

There’s no good guide to sleep or shutdown cause numbers, I’m afraid. Generally, positive numbers indicate a software reason, negative numbers a hardware reason. A zero (0) usually signifies a protective SafeSleep when a laptop is conserving the last of its battery power. A cause of 5 means that the sleep was initiated in a normal and orderly way, either from a timer resulting from your Energy Saver settings, or a user action of putting the system to sleep.

For shutdowns, you may also encounter cause 3, which is a ‘dirty’ forced shutdown or restart, which is something you should not encounter in sleep causes.

In Consolation or log show, you can list the cause numbers of previous sleeps using a filter predicate of
processImagePath CONTAINS[c] kernel
AND
eventMessage CONTAINS[c] system wake

The next series of entries can appear in different orders, but show other systems starting to wake up:
19.005252 securityd: [com.apple.securityd.powerwatch] powerstates
19.005253 securityd: [com.apple.securityd.powerwatch] disk
19.005254 securityd: [com.apple.securityd.powerwatch] net
19.005255 securityd: [com.apple.securityd.powerwatch] enter DarkWake
19.005064 configd: (IPConfiguration) [com.apple.IPConfiguration.Server] IPConfiguration: Early Wake
19.006418 apsd: (CoreDaemon) power management notification 0x8019
19.006439 apsd: (CoreDaemon) <APSWakeStateManager: 0x7fbefe722980>: prepareForWakingIntoDarkWake
19.005136 mDNSResponder: [com.apple.mDNSResponder.AllINFO] SnowLeopardPowerChanged F7F00180 0 8019 CPU Network Disk
19.005540 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] -> Powering to On State.
19.005543 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] Capabilities:
19.005546 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] disk
19.005548 blued: (IOBluetooth) [com.apple.bluetooth.CBManager] net
19.005549 blued: (IOBluetooth) [com.apple.bluetooth.CBManager]
19.005262 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] DarkWake:cpu disk net
19.005647 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] DarkWake:cpu disk net
19.006603 sharingd: [com.apple.sharing.Daemon] Power management state 32793
19.006605 sharingd: [com.apple.sharing.Daemon] Dark Wake

Note again that, according to the timestamps, some of those log entries appear out of sequence.

At this stage, you will see a long run of entries from mDNSResponder, starting with something like:
19.005458 mDNSResponder: [com.apple.mDNSResponder.AllINFO] SystemWakeForNetworkAccess: Wake On LAN: 1
19.005460 mDNSResponder: [com.apple.mDNSResponder.AllINFO] SnowLeopardPowerChanged: Waking up, Acking Wakeup, SleepLimit 0 SleepState 2
19.005461 mDNSResponder: [com.apple.mDNSResponder.AllINFO] Waking (old state 2) at 0
19.005466 mDNSResponder: [com.apple.mDNSResponder.AllINFO] mDNSCoreMachineSleep waking: NextSRVUpdate in 1000 -1476983970
19.005469 mDNSResponder: [com.apple.mDNSResponder.AllINFO] mDNSCoreMachineSleep: 32 http://www.everestjs.net.edgekey-staging.net. CNAME e1164.c.akamaiedge-staging.net.: Adjusted the remain ttl 12583 by 1156 seconds

There is here an odd incongruity in the privacy provided by the new log system: in many places, log entries are redacted using <private> to the point where they are almost worthless. Yet when mDNSResponder fires up here, it lists in full a large number of internet addresses which have been cached for long periods of time, and could be used when reconstructing an internet use history!

The next kernel entries occur as other hardware services are reinstated:
19.017049 kernel: (AppleThunderboltNHI) 182911405812us AppleThunderboltNHIType2::prePCIWake - power up complete - took 1 us
19.017050 kernel: (AppleThunderboltNHI) AppleThunderboltNHIType2::prePCIWake - power up complete - took 1 us
19.017303 kernel: (AirPortBrcm4360) ARPT: 182911.406066: wl0: leaveModulePoweredForOffloads: Wi-Fi will stay on.
19.017328 kernel: (AirPortBrcm4360) ARPT: 182911.406092: AirPort_Brcm43xx::syncPowerState: WWEN[disabled]
19.122543 kernel: (IOThunderboltFamily) IOThunderboltSwitch<0x0>(0x0)::listenerCallback - Thunderbolt HPD packet for route = 0x0 port = 11 unplug = 0
19.122615 kernel: (IOThunderboltFamily) IOThunderboltSwitch<0x0>(0x0)::listenerCallback - Thunderbolt HPD packet for route = 0x0 port = 12 unplug = 0
19.122574 securityd: [com.apple.securityd.powerwatch] system will power on
19.122578 securityd: [com.apple.securityd.SS] 0x7fff5b611b30 will power on
19.122629 securityd: [com.apple.securityd.powerwatch] sending no response
19.122312 configd: (CaptiveNetworkSupport) [com.apple.captive.Controller] Wake
19.123709 kernel: PMRD: full wake promotion (reason 1) 123 ms
19.123710 kernel: full wake promotion (reason 1) 123 ms
19.124244 kernel: PMRD: prevent idle sleep list: IODisplayWrangler+ (1)
19.124245 kernel: prevent idle sleep list: IODisplayWrangler+ (1)
19.123565 sharingd: [com.apple.sharing.AirDrop] Screen turned on
19.123572 sharingd: [com.apple.sharing.AirDrop] Scanning mode off: console=1, discoverable=0, screenOn=1, unlockedOnce=1
19.124541 sharingd: (CoreUtils) [com.apple.sharing.SDNearbyAgentCore] Screen state changed to on
19.124550 sharingd: (CoreUtils) [com.apple.sharing.SDNearbyAgentCore] Activity level changed 1 (Disabled) -> 7 (Screen)
19.125062 powerd: rootDomain's user activity state:1
19.125074 powerd: Display state: On
19.125084 powerd: Activity changes from 0x0 to 0x1. UseActiveState:1
19.125085 powerd: hidActive:0 displayOff:0 assertionActivityValid:1 now:0x2ca7f hid_ts:0x2c55e assertion_ts:0x2ca7f

Grand Central Dispatch components including CTS and coreduetd are usually starting to appear in log entries by now, for example:
19.124279 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] User <private>
19.123986 UserEventAgent: (com.apple.cts) [com.apple.xpc.activity.All] User <private>
19.124836 coreduetd: [com.apple.coreduet.admissionCheck.] Incoming using send_message_with_reply
19.124842 coreduetd: [com.apple.coreduet.admissionCheck.] Received [CDDProtocolMessageTypeTAttributeOccurred] message, msgtype = [52], from clientId [10]...
19.124854 coreduetd: [com.apple.coreduet.admissionCheck.] Attribute with Id [45064] occurred with value [<private>], rising edge [1], falling edge [0]
19.125751 UserEventAgent: (BluetoothUserAgent-Plugin) [com.apple.bluetooth.User Agent] [BTUserEventAgentController hostControllerPoweredOn] on = 0 off = 14718
19.125752 UserEventAgent: (BluetoothUserAgent-Plugin) [com.apple.bluetooth.User Agent] [BTUserEventAgentController messageTracerEventDriven] hostControllerPoweredOn
19.125753 UserEventAgent: (BluetoothUserAgent-Plugin) [com.apple.bluetooth.User Agent] [BTUserEventAgentController messageTracerEventDriven]

With these come entries concerning Bluetooth, AirDrop, and the widening range of services which are being reinstated.

Hopefully this has given you a broad overview of what you can expect to see in the first 130 milliseconds after the start of a system wake, and it will help you identify any problems which may have occurred then.