Converting Unified Logs – A Great Disturbance In The Force
“I felt a great disturbance in The Force; as if millions of timestamps suddenly cried out in terror and were suddenly wrong. I fear something terrible has happened.” – Obi-Wan Kenobi (sort of.)
A few months ago, I started working on a series of Unified Logs articles on my personal blog, mac4n6.com. In the first entry, I dealt with the manual creation of a logarchive bundle and subsequent conversion of these logs on Catalina (10.15) systems. The creation of these logarchive bundles was easy enough on prior versions of macOS when the log executable would suggest the conversion using the “force” argument.
Like Obi-Wan, I felt something was awry and did some testing. I was working off the assumption that the timestamps I saw, after converting as Apple log suggested on a 10.13 system, were correct.
I was wrong.
After much more extensive testing across different systems, versions, and platforms, I have determined that using –force will show incorrect timestamps, sometimes by fractions of a second or sometimes by much longer!
To test this, I executed a command that I knew would create a specific and easy-to-find event in the Unified Logs.
I collected the logs using the log-preferred method, “log collect.” I also manually created a logarchive bundle using a recursive copy on the diagnostics and uuidtext directories.
When creating a manual logarchive bundle on a live system, ownership must be changed from root due to the recursive copy.
Copies of the manually created logarchive bundle were then made to test different versions of the OSArchiveVersion in the logarchive bundle’s Info.plist. (In my previous research, this was the only key that log cared about when reading these logs.)
To determine the correct timestamp, I searched for the “ITS A TRAP” message on the live system and in the log collect logarchive bundle. The timestamp of this event is 2020-09-28 12:43:32.488861-0400 using both methods.
The next step was to convert the manually created logarchive bundles. In my previous article, the “fix” was to create an entry in the Info.plist file in the root of the logarchive bundle where the key OSArchiveVersion set to 2.
My testing shows that this should actually be a 4 (a 3 will also work, however, the current version is a 4.) This can be done by using the command below on macOS. This was tested on macOS 10.12 – 10.15 and iOS 13 & 14 (older iOS versions should likely act similarly.)
/usr/libexec/PlistBuddy -c “Add :OSArchiveVersion integer 4” itsatrap.logarchive/Info.plist
In the example below, log show was attempted on a 10.15 system without conversion first. The first error encountered read:
“log: Could not open log archive: The log archive is corrupt or incomplete and cannot be read.”
The PlistBuddy command was used to make it Version 2 of the logarchive bundle.
The log show command was run again, and provided this error:
“log: Archive format needs updating (to version 4), doing so will render the archive unreadable by older tools.
Re-run log with –force if you want to allow this upgrade
Previous to 10.15, the –force archive update message would be offered to the user. This is an example of a log showing on 10.14.6. No Info.plist file addition would be required.
Using the recommended –force argument on the command, I performed the “upgrade” to Version 4 logarchive bundle. It gave another error which read:
“log: warning: The log archive contains partial or missing metadata
log: Could not open log archive: The log archive is corrupt or incomplete and cannot be read”
Executing the log show command again produces the correct message and the error:
“log: warning: The log archive contains partial or missing metadata”
Unfortunately, the timestamp is slightly off 2020-09-28 12:43:32.509152-0400, compared with the appropriate timestamp of 2020-09-28 12:43:32.488861-0400.
The same actions performed on a Version 3 or Version 4 will show the appropriate timestamp. Many of the same “errors” persist. However, the –force was not suggested and the timestamps are correct.
When a user chooses to follow Apple’s log guidance on using –force to “upgrade” their logarchive bundle, it will change the timesync files. These timesync files provide the time offsets for the timestamps stored in the binary tracev3 files. The timesync files in Version 2 of the logarchive bundle have been changed, all other conversions stayed the same.
While these timestamps were off by fractions of a second, in one of my previous tests they were off by quite a few days!
As Yoda would say “The greatest teacher, failure is.” This is a good demonstration of why making assumptions may lead to wrong outcomes. Testing should always be done to verify the results.
If you do not want to deal with the manual creation of these logarchive bundles, just a reminder that Inspector can parse the logs for you!