Bugs in the logs: Sierra’s new logs are far from perfect

I have whinged that Sierra’s Console 1.0 is next to useless for working with historic log data and post hoc diagnosis, and pointed you towards the log command in Terminal.

I’m afraid that I now have to warn you that, as currently provided in Sierra 10.12, log has some major bugs which seriously limit its usefulness – yes, for working with historic log data and post hoc diagnosis.

These bugs are in its show command, which is the only tool currently provided with Sierra for examining events which have already occurred. They appear confined to the --start and --end options, which allow you to limit the window of logs to be shown.

For example, if you use a command like
log show --predicate 'subsystem == "com.apple.TimeMachine"' --style syslog --start '2016-10-03 14:00:00' --end '2016-10-03 18:00:00' --info
at 18:10, you would expect to see at least one or two Time Machine backups being completed. Chances are that such a command will find none. If you were to use instead a command like
log show --predicate 'subsystem == "com.apple.TimeMachine"' --style syslog --info --last 4h
at 18:10, you will see those backups.

Using --start and --end options with a predicate almost always seem to result in a blank return.

Even used without a predicate, the --start and --end options lose a lot of log entries, which can be alleviated by widening the time window.

For example,
log show --start '2016-10-03 15:40:00' --end '2016-10-03 15:41:00' --info
returned just 5 log entries in that one-minute window. But widening the time window with
log show --start '2016-10-03 15:39:00' --end '2016-10-03 15:42:00' --info
returned 26 entries for that same one-minute window.

This appears to be independent of other options, such as the --style option, so the only workaround, if you want to obtain a historic time window from the logs, is to widen that window and avoid the use of any predicates. Even then, log show may still not return log entries which are held for that period.

The good news is that the --last option does not appear to have any bugs, so you can still retrieve reliable log information for time periods up to the present. However, you cannot use the --start or --end options to limit the window returned when using --last: you can either use --start and --end (bugs and all), or --last, but not both together.

It is possibly these bugs which are currently preventing any useful tools in Console 1.0 for the examination of historic log data, as without --start and --end options, most attempts to look at such data end up being overwhelmed with unusable quantities of log records.

I will add these bugs to the list of known bugs in Sierra very shortly.