Did it freeze? Missing 50 minutes of log

I was running through a standard suite of tests performed by a product which I was reviewing. One step examined the file system metadata on my internal boot disk, and warned that during this my Mac would be unresponsive for a while, and so it was.

For the next twenty minutes, the clock was frozen, and all I could do was move the pointer. I couldn’t perform any actions with the pointer other than waggle it around on screen, and there was nothing to indicate that my iMac Pro was doing anything other than sitting there frozen.

Twenty minutes is an eternity when you’re waiting for a Mac to recover. I had other things to get on with, and by now suspected that something quite terminal had happened. I pressed and held the Power button to force it to shut down. Because the app had last been seen rummaging through my boot disk metadata, I hooked up my keyboard to a USB port and started the Mac up in Recovery mode.

Once I had mounted my internal SSD – having a T2 chip, it’s fully encrypted – Disk Utility took another half an hour or so checking each of twenty-five snapshots on the disk before it pronounced the boot disk fit and healthy, and I could finally restart into normal mode.

I still wasn’t sure, though, whether the Mac had simply frozen or I had been too impatient to let it complete its task. The only way of knowing what might have gone on was to browse the unified log for the period in which my Mac had been unresponsive. I got quite a surprise, though, when I did that using Consolation 3.

missinglog

From 08:41:51 until I restarted the Mac at 09:32:22, throughout the period in which it was unresponsive or booted in Recovery mode, the unified log was missing.

The last entries are a torrent from DiskArbitration indicating a period of intensive access to the file system, as you might expect given the nature of the tests that were being performed at the time. The menubar clock actually stopped at 08:43, a couple of minutes after the last entry in the log. There’s nothing untoward before them, then at 08:41:51 they suddenly stop dead.

The next entry in the log is announcement of the start of the boot process at 09:32, when the Mac was restarting after its visit to Recovery mode. That proceeded according to plan, and to my great relief my iMac Pro bounced back in fine fettle, none the worse for its time in limbo.

Log entries are absent for two reasons:

  • From 08:41 until the Mac was forced to shut down at a little after 09:00, the boot disk appears to have been locked, and therefore log files couldn’t be written to it. When I forced it to shut down, any log entries held in memory were lost.
  • From startup in Recovery mode soon after 09:00 until restarting at 09:32, the Mac was running in Recovery mode, which doesn’t apparently keep logs.

According to the man page for diskarbitrationd, last revised in the summer of 2004 – almost fifteen years ago now – it writes logs to /var/log/diskarbitrationd.log, but of course since the introduction of the unified log, that doesn’t appear to be the case. Even if it still did that, it too would have been constrained to silence for the same reasons that the unified log was.

I’m left none the wiser. Did my Mac freeze, or should I have waited another few seconds or minutes for it to complete? In the absence of any indicator in the app that it was still happily checking the file system metadata, it’s impossible to tell at the time, and no easier after the event. Even if an app can’t risk displaying any progress bar or more precise indicator, it could switch between simple characters such as / – \ to give the user some visual feedback.

But why are logs so often the first thing to stop working just when you most need them?