Reading logs: waking from sleep and backing up

Two common events which you will see in your logs are waking up from sleep, and making a backup using Time Machine. These are useful landmarks in your logs, and important events which need to run correctly, making them worth understanding.

Waking up

Problems and crashes which occur when waking the system up from sleep can be impossible to diagnose and fix without using the logs. Although you will see additional messages, these are the key stages which you are likely to encounter.

07/07/2016 11:46:42.000 kernel[0]: STEX : setPowerState : 0, (0 = sleep , 1 = pause, 2 = wake)
07/07/2016 11:46:42.000 kernel[0]: STEX : Going to sleep, outstanding IO = 0
07/07/2016 11:46:42.000 kernel[0]: STEX : setPowerState done

Oddly the first events logged when you start waking your Mac up are usually those indicating that it is going back to sleep.

07/07/2016 10:44:16.000 kernel[0]: AppleThunderboltNHIType2::waitForOk2Go2Sx - intel_rp = 1 dlla_reporting_supported = 1
07/07/2016 11:46:42.000 kernel[0]: AppleThunderboltNHIType2::waitForOk2Go2Sx - retries = 30000

Those are normally followed by a couple of odd reports from the Thunderbolt subsystem. Note that the first is out of time sequence: this should not happen, but now appears quite normal.

07/07/2016 11:46:42.000 kernel[0]: Wake reason: XHC1
07/07/2016 11:46:42.000 kernel[0]: Previous sleep cause: 5
07/07/2016 11:46:42.000 syslogd[60]: ASL Sender Statistics
07/07/2016 11:46:42.000 kernel[0]: AppleThunderboltNHIType2::prePCIWake - power up complete - took 2 us
07/07/2016 11:46:42.000 kernel[0]: ARPT: 40601.606994: wl0: leaveModulePoweredForOffloads: Wi-Fi will stay on.
07/07/2016 11:46:42.000 kernel[0]: ARPT: 40601.607012: AirPort_Brcm43xx::syncPowerState: WWEN[disabled]

This is the start of the wake-up sequence proper, giving the cause for the sleep, then preparing communications links.

07/07/2016 11:46:42.000 kernel[0]: AppleThunderboltGenericHAL::earlyWake - complete - took 809 milliseconds
07/07/2016 11:46:42.000 kernel[0]: STEX : setPowerState : 2, (0 = sleep , 1 = pause, 2 = wake)
07/07/2016 11:46:42.000 kernel[0]: STEX : Power on device
07/07/2016 11:46:42.000 kernel[0]: STEX : Machine Model : iMac17,1
07/07/2016 11:46:42.000 kernel[0]: STEX : fw is READY to do handshake
07/07/2016 11:46:42.000 kernel[0]: STEX : Sending Host Model Name : iMac17,1
07/07/2016 11:46:42.000 kernel[0]: STEX : Sending Host Build Version : 15F34
07/07/2016 11:46:42.000 kernel[0]: [ PCI configuration begin ]
07/07/2016 11:46:42.000 kernel[0]: [ PCI configuration end, bridges 16, devices 17 ]
07/07/2016 11:46:43.000 kernel[0]: [IOBluetoothHCIController][WakeUpDisplay] -- took 1048849 microseconds to call activityTickle()
07/07/2016 11:46:43.000 kernel[0]: full wake promotion (reason 1) 1050 ms
07/07/2016 11:46:43.051 CommCenter[335]: Telling CSI to exit low power.
07/07/2016 11:46:43.000 kernel[0]: STEX : scatch Data = 0

The Power State is now set to be ‘wake’, and the Mac is fully powered up again.

07/07/2016 11:46:43.000 kernel[0]: Ethernet [AppleBCM5701Ethernet]: Link up on en0, 100-Megabit, Full-duplex, Symmetric flow-control, Debug [796d,2301,0de1,0300,45e1,0000]
07/07/2016 11:46:46.409 ntpd[244]: wake time set +2.234229 s

This is the Ethernet network connection being restored. These settings should match those attained at the last startup.

07/07/2016 11:46:55.000 kernel[0]: STEX : handshake with FW successfully, Device#1
07/07/2016 11:46:55.000 kernel[0]: STEX : setPowerState done
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40612.719489: AirPort_Brcm43xx::powerChange: System Wake - Full Wake/ Dark Wake / Maintenance wake
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220074: IOPMPowerSource Information: onWake, SleepType: Normal Sleep,
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220122: AirPort_Brcm43xx::platformWoWEnable: WWEN[disable]
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220776: ChangeVCO => vco:960, xtalF:40, frac: 98, ndivMode: 3, ndivint: 24
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220780: Data written into the PLL_CNTRL_ADDR2: 00000c31
07/07/2016 11:46:55.000 kernel[0]: ARPT: 40613.220816: Data written into the PLL_CNTRL_ADDR3 (Fractional): 0000100e
07/07/2016 11:46:56.000 kernel[0]: [HID] [ATC] AppleDeviceManagementHIDEventService::processWakeReason Wake reason: Button (0x03)
07/07/2016 11:46:56.000 kernel[0]: [HID] [ATC] AppleDeviceManagementHIDEventService::processWakeReason Wake reason: Host (0x01)
07/07/2016 11:46:56.000 kernel[0]: ARPT: 40613.613462: AirPort_Brcm43xx::syncPowerState: WWEN[disabled]
07/07/2016 11:46:56.000 kernel[0]: PM response took 394 ms (73, powerd)
07/07/2016 11:46:56.257 sharingd[356]: 11:46:56.256 : Starting AirDrop server for user 501 on wake

All remaining subsystems are woken up and ready for use. Your logs should resume normal entries.

You may also see custom processes being launched by launchd. In this vanilla configuration of El Capitan 10.11.5, there are no such customisations. If yours does launch additional processes, then you will need to check those for errors, which could (and often are) be the cause of your problems.

Time Machine backup

When awake and connected to the backup store, this should occur every hour. If you are using your Mac at the time, these log entries may become interspersed with messages relating to your other activities, but you can normally recognise this sequence as it happens in the background.

07/07/2016 07:47:17.053[7985]: Starting automatic backup
07/07/2016 07:47:17.268[7985]: Backing up to /dev/disk3s2: /Volumes/PROMISE PEGASUS/Backups.backupdb
07/07/2016 07:47:18.834[7985]: Will copy (304.1 MB) from Macintosh HD
07/07/2016 07:47:18.834[7985]: Found 239 files (304.1 MB) needing backup
07/07/2016 07:47:18.863[7985]: 14.63 GB required (including padding), 3.23 TB available

Time Machine’s backupd process announces that it is starting a timed backup, which volume it is going to back up to, then works out what needs to be backed up. It gives details of the number of files and space required to do this, and tells you how much free space remains on the backup volume before the backup is made.

07/07/2016 07:51:01.273[7985]: Copied 360 items (304 MB) from volume Macintosh HD. Linked 9332.
07/07/2016 07:51:08.237[7985]: Created new backup: 2016-07-07-075106

Once the backup is complete, it reports what it did actually back up, and tells you the name of that backup. The backup consists of a combination of new files, here 360 in all, and links from existing files, here over nine thousand. These should be similar to the number it first identified, but may not be exactly the same. This also tells you which volume the files were copied from. The time of creation of the new backup given here, less the starting time above, tells you how long the backup took – in this case, less than 4 minutes in all.

07/07/2016 07:51:09.000 kernel[0]: hfs: mounted Recovery HD on device disk0s3
07/07/2016 07:51:09.957 mds[83]: (Volume.Normal:2464) volume:0x7fc7ca8bf000 ********** Bootstrapped Creating a default store:0 SpotLoc:(null) SpotVerLoc:(null) occlude:0 /Volumes/Recovery HD
07/07/2016 07:51:10.004 fseventsd[65]: Logging disabled completely for device:1: /Volumes/Recovery HD

The Recovery partition is then mounted.

07/07/2016 07:51:10.048[7985]: Starting post-backup thinning
07/07/2016 07:51:10.000 kernel[0]: hfs: unmount initiated on Recovery HD on device disk0s3
07/07/2016 07:54:15.363[7985]: Deleted /Volumes/PROMISE PEGASUS/Backups.backupdb/Howard’s iMac/2016-07-06-065322 (27.1 MB)
07/07/2016 07:54:15.363[7985]: Post-backup thinning complete: 1 expired backups removed

backupd then performs housekeeping on the backups, removing any expired backups to reclaim space. The Recovery partition is also unmounted again.

07/07/2016 07:54:19.280[7985]: Backup completed successfully.
Successful completion occurred.

So reading logs is not as daunting as you might think, is it?