Apple has a number of different logging APIs. For the past few releases, Apple has tried to capture everything possible in logs, creating what many administrators and developers might consider to be a lot of chatter. As such, an entirely new interface needed to be developed to categorize and filter messages sent into system logs.
Writing Logs
The logger command is still used to create entries in system logs. However, if you are then using tail to view /var/log/system.log then you will notice that you no longer see your entry being written. This is because as the logs being created in macOS have gotten more complex, the tools to read and write those logs has gotten more complicated as well.
Let’s take a simple log entry. Below, we’ll write the string “Hello Logs” into the system log. To do so, use the –i option to put the process id of the logger process and –s to write to the system log, as well as to stderr. To make the entry easier we’ll tag it with –t followed by the string of the tag. And finally, we’ll quote the entry we want written into the log. This is basically the simplest form of an entry:
logger -is -t krypted "Hello Logs"
Once written, use the log command to read your spiffy new entries. This isn’t terribly different than how things worked previously. If you’re a developer, you will need to note that all of the legacy APIs you might be using, which include asl_log_message, NSLog, and syslog, have been redirected to the new Unified Logging system, provided you build software for 10.12 (you can still build as before for 10.11, iOS 9, tvOS 10, and watchOS 3 and below). These are replaced with the os_log, os_log_info, os_log_debug, os_log_error, os_log_fault, and os_log_create APIs (which correspond to various levels of logs that are written).
Reading Logs
Logs are now stored in the tracev3 formatted files in /var/db/diagnostics, which is a compressed binary format. As with all binary files, you’ll need new tools to read the files. Console has been updated with a new hierarchical capability and the ability to watch activities, subsystems, etc.
The log command provides another means of reading those spiffy new logs. To get started, first check out the man page:
man log
That “Hello Logs” string we used earlier is part of a message that you can easily view using the ‘log show’ command. In the below example, we’ll just run a scan of the last 3 minutes, using the –last option, and then providing a –predicate. We’ll explain those a bit later, but think of it as query parameters – here, we’ll specify to look for “Hello Logs” in eventMessage:
log show --predicate 'eventMessage contains "Hello Logs"' --last 3m
Filtering the log data using “eventMessage CONTAINS “Hello Logs”” shows us that our entry appears as follows:
Timestamp Thread Type Activity PID
2017-03-23 23:51:05.236542-0500 0x4b83bb Default 0x0 88294 logger: Hello Logs
——————————————————————————————————————–
Log – Default: 1, Info: 0, Debug: 0, Error: 0, Fault: 0
Activity – Create: 0, Transition: 0, Actions: 0
How do you find out what to use where? Here’s an example where I’m going to try to find all invalid login attempts. First, I’m just going to watch the logs. Many will prefer the “log stream’ command. I’m actually going to just use show again, because I like the way it looks more. I’m also going to use log with the syslog –style so it’s easier to read (for me at least), and then here I’m just looking at everything by specifying a space instead of an actual search term:
log show --style syslog --predicate 'eventMessage contains " "' --info --last 24h
Looking at the output, you can see an entry similar to the following:
2017-03-23 14:01:43.953929-0500 localhost authorizationhost[82865]: Failed to authenticate user <admin> (error: 9).
Oh, I’ve got to just search for Failed to authenticate user” and I’ll be able to count invalid login attempts. To then take this and place it into a command that, for example, I could build an extension attribute using, I can then just find each entry in eventMessage that contains the string, as follows:
log show --style syslog --predicate 'eventMessage contains "Failed to authenticate user"' --info --last 1d
As with many tools, once you have a couple of basic incantations, they become infinitely simpler to understand. These few commands basically get you back to where you were with tailing logs. If you want to get that –f functionality from tail, to watch the logs live, just swap show with stream. The most basic incantation of this would just be ‘log stream’ without bothering to constrain the output:
log stream
Running this is going to spew so much data into your terminal session. So to narrow down what you’re looking for, let’s look at events for Twitter:
log stream --predicate 'eventMessage contains "Twitter"'
You can also view other logs and archives, by calling a file name:
log show system_logs.logarchive
Organization and Classification
The new logging format also comes with Subsystems. If you’re a developer you’ll be able to file your messages into, for example, a com.yourname.whatevers domain space, so you can easily find your log messages. You can also build categories, and of course, as we noted previously, tag. So there are about as many ways to find log entries as you can possibly ask for. Apple has a number of subsystems built into macOS. I put together a list of Apple subsystems into a class that you should be able to throw into your python projects at https://gist.github.com/krypted/495e48a995b2c08d25dc4f67358d1983.
You also have different logging levels. These include the basic levels of Default, Info, and Debug. You also have two special levels available: Fault and Error. All of this is to add hierarchical logs (which makes tracing events a much more lovely experience) and protecting privacy of end users (think sandbox for logs). I’d recommend watching the WWDC session where Unified Logging was introduced at https://developer.apple.com/videos/play/wwdc2016/721 if you’re interested in learning more about these types of things, especially if you’ll be building software that makes use of these new logging features.
The one thing that’s worth mentioning for the Mac Techs out there, is how you would go about switching between logging levels for each subsystem. This is done with the ‘log config’ command. Here, I’ll use the –mode option to set the level to debug, and then defining the substyem to do so with using the –subsystem option:
log config --mode "level:debug" --subsystem com.krypted
If you have a particularly dastardly app, the above might just help you troubleshoot a bit. As mentioned earlier, we also have these predicates, which you can think of as metadata in the searching context. These include the following:
- category: category of a log entry
- eventMessage: searches the activity or message
- eventType: type of events that created the entry (e.g. logEvent, traceEvent)
- messageType – type or level of a log entry
- processImagePath: name of the process that logged the event
- senderImagePath: not all entries are created by processes, so this also includes libraries and executables
- subsystem: The name of the subsystem that logged an event
Comparisons and Searches
OK, now let’s make things just a tad bit more complicated. We’ll do this by stringing together search parameters. Here, we have a number of operators available to us, similar to what you see in SQL. These include:
- && or AND to indicate two matches
- || or OR indicates one of the patterns matches
- ! or NOT searches for items that the patterns don’t match for, which is useful for filtering out false positives in scripts
- = to indicate that one search matches a pattern or is equal to
- != to indicate that the search is not equal to
- > is greater than
- < is less than
- => means greater than or equal to
- =< means less than or equal to
- CONTAINS indicates a string matches a given pattern with case sensitivity
- CONTAINS[c] indicates a string matches a given pattern without case sensitivity
- BEGINSWITH indicates a string begins with a given pattern
- ENDSWITH indicates that a string ends with a given pattern
- LIKE indicates a pattern is similar to what you’re searching for
- MATCHES indicates that two text strings match
- ANY, SOME, NONE, IN are used for pattern matching in arrays
- NULL indicates a NULL response (for example, you see “with error (NULL)” in logs a lot)
To put these into context, let’s use one in an example. Thus far my most common as been a compound search, so matching both patterns. Here, we’ll look at the WirelessProximity subsystem for Bluetooth and we’ll look at how often it’s scanning for new devices, keeping both patterns to match inside their own parenthesis, with all patterns stored inside single quotes, as follows:
log show --style syslog --predicate '(subsystem == "com.apple.bluetooth.WirelessProximity") && (eventMessage CONTAINS[c] "scanning")' --info --last 1h
Developers and systems administrators will find that the Apple guide on predicate programming, available at https://developer.apple.com/library/prerelease/content/documentation/Cocoa/Conceptual/Predicates/AdditionalChapters/Introduction.html, to be pretty useful if you’re doing lots of this kind of work.
Note: sysdiagnose, a tool long used for capture diagnostics information to include in bug reports, is still functional, and now includes Unified Logging information, so Apple developers can get a complete picture of what’s going on in systems.
Conclusion
Ultimately, the new Unified Logging is a bit more complicated than the previous options for both creating and reading logs. But once you get used to it, you’ll log it – I mean, love it. I find that I use less grep and awk and get more concise results. I also like the fact that the same code is useable with all four platforms, so learn once and re-use across devices. There’s a lot of information out there, but I had to go hunting around. Hopefully having a number of links and a the structure used in this article makes it easier to learn how to use all these new new little toys! Good luck!
