Logs, Logging, And Logger (Oh My)!

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.


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!

macOS Logging Subsystems In A Gist

If you happen to be tweaking the macOS subsystems for logging, I’ve put them into a little python class. If you need it, find it at this gist: https://gist.github.com/krypted/495e48a995b2c08d25dc4f67358d1983 Could use an array of all the levels, TTLs, and options. But I’ll get to that when I get some time. If this is all you need, though: class Logging(object): __name__ = 'logger.info(1)' plist = '/System/Library/Preferences/Logging/Subsystems/' def __init__(__name__, plist, *args, **kwargs): super(getLogger/, self).__init__() logger.info('Input parameters:\n' 'accessibility: "{com.apple.Accessibility.plist}"\n' 'StandaloneHIDFudPlugins: "{com.apple.StandaloneHIDFudPlugins.plist}"\n' 'duetactivityscheduler: "{com.apple.duetactivityscheduler.plist}"\n' 'passkit: "{com.apple.passkit.plist}"\n' 'AppKit: "{com.apple.AppKit.plist}"\n' 'SystemConfiguration: "{com.apple.SystemConfiguration.plist}"\n' 'eapol: "{com.apple.eapol.plist}"\n' 'persona: "{com.apple.persona.plist}"\n' 'AppleIR: "{com.apple.AppleIR.plist}"\n' 'TCC: "{com.apple.TCC.plist}"\n' 'icloudpreferences: "{com.apple.icloudpreferences.plist}"\n' 'apple.pf: "{com.apple.pf.plist}"\n' 'AssetCache: "{com.apple.AssetCache.plist}"\n' 'TimeMachine: "{com.apple.TimeMachine.plist}"\n' 'internetAccounts: "{com.apple.internetAccounts.plist}"\n' 'photoanalysisd.graph: "{com.apple.photoanalysisd.graph.plist}"\n' 'AssetCacheServices: "{com.apple.AssetCacheServices.plist}"\n' 'Transport: "{com.apple.Transport.plist}"\n' 'libsqlite3: "{com.apple.libsqlite3.plist}"\n' 'photoanalysisd.job: "{com.apple.photoanalysisd.job.plist}"\n' 'BezelServices: "{com.apple.BezelServices.plist}"\n' 'accounts: "{com.apple.accounts.plist}"\n' 'locationd.Core: "{com.apple.locationd.Core.plist}"\n' 'photoanalysisd: "{com.apple.photoanalysisd.plist}"\n' 'DesktopServices: "{com.apple.DesktopServices.plist}"\n' 'amp.MediaServices: "{com.apple.amp.MediaServices.plist}"\n' 'locationd.Legacy: "{com.apple.locationd.Legacy.plist}"\n' 'pluginkit: "{com.apple.pluginkit.plist}"\n' 'ExchangeWebServices: "{com.apple.ExchangeWebServices.plist}"\n' 'authkit: "{com.apple.authkit.plist}"\n' 'locationd.Motion: "{com.apple.locationd.Motion.plist}"\n' 'sandbox.reporting: "{com.apple.sandbox.reporting.plist}"\n' 'FaceTime: "{com.apple.FaceTime.plist}"\n' 'avfaudio: "{com.apple.avfaudio.plist}"\n' 'locationd.Position: "{com.apple.locationd.Position.plist}"\n' 'sbd: "{com.apple.sbd.plist}"\n' 'Finder: "{com.apple.Finder.plist}"\n' 'awd.awdd: "{com.apple.awd.awdd.plist}"\n' 'locationd.Utility: "{com.apple.locationd.Utility.plist}"\n' 'securityd: "{com.apple.securityd.plist}"\n' 'HTTPServer: "{com.apple.HTTPServer.plist}"\n' 'awd.framework: "{com.apple.awd.framework.plist}"\n' 'mDNSResponder: "{com.apple.mDNSResponder.plist}"\n' 'sharing: "{com.apple.sharing.plist}"\n' 'IDS: "{com.apple.IDS.plist}"\n' 'bluetooth: "{com.apple.bluetooth.plist}"\n' 'mac.install: "{com.apple.mac.install.plist}"\n' 'siri: "{com.apple.siri.plist}"\n' 'IPConfiguration: "{com.apple.IPConfiguration.plist}"\n' 'calendar: "{com.apple.calendar.plist}"\n' 'mail: "{com.apple.mail.plist}"\n' 'social: "{com.apple.social.plist}"\n' 'ManagedClient: "{com.apple.ManagedClient.plist}"\n' 'captive: "{com.apple.captive.plist}"\n' 'mediaremote: "{com.apple.mediaremote.plist}"\n' 'socialpushagent: "{com.apple.socialpushagent.plist}"\n' 'Messages: "{com.apple.Messages.plist}"\n' 'catalyst: "{com.apple.catalyst.plist}"\n' 'multipeerconnectivity: "{com.apple.multipeerconnectivity.plist}"\n' 'symptomsd: "{com.apple.symptomsd.plist}"\n' 'MessagesEvents: "{com.apple.MessagesEvents.plist}"\n' 'cdp: "{com.apple.cdp.plist}"\n' 'network: "{com.apple.network.plist}"\n' 'syncdefaults: "{com.apple.syncdefaults.plist}"\n' 'NetworkSharing: "{com.apple.NetworkSharing.plist}"\n' 'clouddocs: "{com.apple.clouddocs.plist}"\n' 'networkextension: "{com.apple.networkextension.plist}"\n' 'useractivity: "{com.apple.useractivity.plist}"\n' 'ProtectedCloudStorage: "{com.apple.ProtectedCloudStorage.plist}"\n' 'coreanimation: "{com.apple.coreanimation.plist}"\n' 'networkserviceproxy: "{com.apple.networkserviceproxy.plist}"\n' 'Registration: "{com.apple.Registration.plist}"\n' 'coreaudio: "{com.apple.coreaudio.plist}"\n' 'nlcd: "{com.apple.nlcd.plist}"\n' 'SkyLight: "{com.apple.SkyLight.plist}"\n' 'coredata: "{com.apple.coredata.plist}"\n' 'notes: "{com.apple.notes.plist}"\n' try: plist() except Exception as e: logger.error(e)

Increase The Logging Level Of Apple Configurator

Apple Configurator, by default, logs only a limited amount of data. To increase the logging level for Apple Configurator, use the defaults command to write All into the LogLevel key in com.apple.configurator, using the defaults command: defaults write com.apple.configurator LogLevel ALL Re-open Apple Configurator and you’re golden. Then, have some problems and be so happy to get some logs, viewable in Console. defaults read com.apple.configurator {AcceptedLicenseVersion = 20150317; CDFirstLaunch = 0; CDMainViewType = 3; ChaperoneCertificateIssuer = ; ChaperoneCertificateSerial = ; LogLevel = ALL; NSNavLastRootDirectory = "~/Desktop"; NSNavPanelExpandedSizeForSaveMode = "{712, 620}"; "NSToolbar Configuration C484E2C8-5B9C-4999-9304-7233D38B3F95" = { "TB Display Mode" = 1; "TB Icon Size Mode" = 1; "TB Is Shown" = 1; "TB Size Mode" = 1;}; "NSWindow Frame CDMainWindow" = "458 164 875 550 0 0 1366 745 "; "NSWindow Frame NSNavPanelAutosaveName" = "783 504 424 192 0 0 1366 745 "; SignConfigurationProfileOnExport = 0; SuppressPrepareInterlockDialog = 0;} Viola, that’s it!

Yosemite Server And Logs

OS X Yosemite running the Server app has a lot of scripts used for enabling services, setting states, changing hostnames and the like. Once upon a time there was a script for OS X Server called server setup. It was a beautiful but too simplistic kind of script. Today, much of that logic has been moved out into more granular scripts, kept in /Applications/Server.app/Contents/ServerRoot/System/Library/ServerSetup, used by the server to perform all kinds of tasks. These scripts are, like a lot of other things in Yosemite Server. Some of these include the configuration of amavisd, docecot and alerts. These scripts can also be used for migrating services and data. Sometimes the scripts are in bash, sometimes ruby, sometimes perl and other times even python. And the scripts tend to change year over year/release over release. One of the things that can can be useful about the scripts scattered throughout the Server app is to learn how the developers of OS X Server intend for certain tasks to occur. Looking At Services This is also where I learned that Apple had put an Open Directory backup script in /Applications/Server.app/Contents/ServerRoot/usr/libexec/server_backup/opendirectorybackup (that still requires a password). But what I haven’t seen in all of these logs is bumping up the logging level for services before performing tasks, so that you can see a verbose output of what’s going on. To do this, it looks like we’re going service-by-service. So let’s look alphabetically, starting with Address Book: sudo serveradmin settings addressbook:DefaultLogLevel = “warn” This by defualt logs to /var/log/caldavd/error.log, which is built based on the following, which sets the base: sudo serveradmin settings addressbook:LogRoot=/var/log/caldavd And the following, which sets the file name in that directory: sudo serveradmin settings addressbook:ErrorLogFile=error.log You can change either by changing what comes after the = sign. Next is afp. This service logs output to two places. The first is with errors to the service, using /Library/Logs/AppleFileService/AppleFileServiceError.log, the path designated in the following: sudo serveradmin settings afp:errorLogPath = “/Library/Logs/AppleFileService/AppleFileServiceError.log” The second location logs activities (open file, delete file, etc) rather than errors and is /Library/Logs/AppleFileService/AppleFileServiceAccess.log, defined using: sudo serveradmin settings afp:activityLogPath = “/Library/Logs/AppleFileService/AppleFileServiceAccess.log” The activity log is disabled by default and enabled using the command: sudo serveradmin settings afp:activityLog = yes The events that trigger log entries are in the afp:loggingAttributes array and are all enabled by default. There are no further controls for the verbosity of the afp logs. The next service is calendar. Similar to address book, the caldav server uses DefaultLogLevel to set how much data gets placed into logs: sudo serveradmin settings calendar:DefaultLogLevel = “warn” This by defualt logs to /var/log/caldavd/error.log, which is built based on the following, which sets the base: sudo serveradmin settings calendar:LogRoot=/var/log/caldavd And the following, which sets the file name in that directory: sudo serveradmin settings calendar:ErrorLogFile=error.log You can changing either by changing what comes after the = sign. Profile Manager is called devicemgr in the serveradmin interface and I’ve found no way to augment the logging levels. Nor does its migration script ( /Applications/Server.app/Contents/ServerRoot/System/Library/ServerSetup/MigrationExtras/80-devicemgrmigration.sh ) point to any increased logging during migration. The dirserv (aka Open Directory) uses the slapconfig back-end, so I use slapconfig to increase logging: sudo slapconfig -enableslapdlog The DNS service uses named.conf, located in /etc to set log levels and has no serveradmin settings for doing so. Here, use the logging section and look for both the file setting (by default /Library/Logs/named.log) for where the log is stored as well as the severity setting, which can set the logging levels higher or lower. By default Messages, or iChat Server, logs a lot. See the following for what is logged: sudo serveradmin settings jabber:logLevel = “ALL” Adding the -D option to the LaunchDaemon that invokes jabber will increase the logs. Logging long-term is handled in each of the xml files that make up the features of jabber. See the Logconfiguration section of the c2s file via: cat /Applications/Server.app/Contents/ServerRoot/private/etc/jabberd/c2s.xml The mail service has a number of options for logging, much of which has to do with the fact that it’s a patchy solution made up of postfix, etc. Global log locations are controlled using the mail:global:service_data_path key, which indicates a path that logs are stored in (as usual many of these are in /Library/Server): sudo serveradmin settings mail:global:service_data_path = "/Library/Server/Mail" To see the virus database logging levels (which should usually be set to warn): sudo serveradmin settings mail:postfix:virus_db_log_level To see the spamassassin logging levels: sudo serveradmin settings mail:postfix:spam_log_level To see the actual postfix logging level: sudo serveradmin settings mail:postfix:log_level To enable timestamps on logs: sudo serveradmin settings mail:imap:logtimestamps = yes To set the dovecot logging to info: sudo serveradmin settings mail:imap:log_level = “info” To set increased logging per function that dovecot performs, see the config files in /Applications/Server.app/Contents/ServerRoot/private/etc/dovecot/default/conf.d, each of which has a logging section to do so. The NetBoot service is simple to configure logging for, simply set the netboot:logging_level to HIGH (by default it’s MEDIUM): sudo serveradmin settings netboot:logging_level = “HIGH” The Postgres service uses a log directory, configured with postgres:log_directory: sudo serveradmin settings postgres:log_directory = “/Library/Logs/PostgreSQL” The /private/etc/raddb/radiusd.conf has a section (log {}) dedicated to configuring how the radius service logs output. The Xsan service logs output per volume to both the System Log and volume-based log files, stored in /Library/Preferences/Xsan/data. The smb service has a file /Library/Preferences/SystemConfiguration/com.apple.smb.server.plist with a key for log level that can be used for more verbose output of the service. The PPTP VPN service logs output to the file specified in vpn:Servers, configured with these: sudo serveradmin settings vpn:Servers:com.apple.ppp.pptp:Server:LogFile = “/var/log/ppp/vpnd.log”
sudo serveradmin settings vpn:Servers:com.apple.ppp.pptp:PPP:LogFile = “/var/log/ppp/vpnd.log”
sudo serveradmin settings vpn:Servers:com.apple.ppp.l2tp:Server:LogFile = “/var/log/ppp/vpnd.log”
sudo serveradmin settings vpn:Servers:com.apple.ppp.l2tp:PPP:LogFile = “/var/log/ppp/vpnd.log” By default, verbose logging is enabled, which you can see with: sudo serveradmin settings vpn:Servers:com.apple.ppp.pptp:Server:VerboseLogging
sudo serveradmin settings vpn:Servers:com.apple.ppp.pptp:PPP:VerboseLogging
sudo serveradmin settings vpn:Servers:com.apple.ppp.l2tp:Server:VerboseLogging
sudo serveradmin settings vpn:Servers:com.apple.ppp.l2tp:PPP:VerboseLogging The last service is web (Apache). The default access logs are per-site, with a key called customLogPath existing for each. The defaultSite uses the following for its logs: sudo serveradmin settings web:defaultSite:customLogPath Swap out the defaultSite with another site to see its log paths. There’s also a key for errorLogPath that shows errors. These are per-site so that administrators can provide access to logs for the owners of each site and not fear them having access to logs for other users. Global error logs are stored in /private/var/log/apache2/error_log as defined in /private/etc/apache2/httpd.conf. Find LogLevel in this file and set it to configure how in depth the logs will be, using debug for the most verbose and info, notice, warn, error, crit, alert, and emerg to get incrementally less information. Additionally the log formats can be set in /private/etc/apache2/httpd.conf, allowing administrators to configure Yosemite Server’s built-in web service to conform to the standards of most modern web log analyzers. Conclusion Overall, there’s a lot of information in these logs and administrators can spend as much time reviewing logs as they want. But other than standard system logs, the output is typically configured on a service-by-service basis. Some services offer a lot of options and others offering only a few. Some services also offer options within the serveradmin environment while others use their traditional locations in their configuration files. I’ll end this with a warning. There can also be a lot of output in these logs. Therefore, if you set the logging facilities high, make sure to keep a watchful eye on the capacity of the location you’re writing logs out to. The reason I looked at paths to logs where applicable was because you might want to consider redirecting logs to an external volume when debugging so as not to fill up a boot volume and cause even more problems than what you’re likely parsing through logs looking to fix…

Mac OS X: Directory Services Debug Log

When you’re trying to troubleshoot issues with Directory Services on Mac OS X sometimes the best thing you can do is put the directoryservices daemon into debug mode. To do so you would use the following command:
killall -USR1 Directory Service
By default errors get trapped into this file:
But when in debug mode using -USR1 you can see more specific errors in the /Library/Logs/DirectoryService/DirectoryService.error.log file.  You can then use commands such as tail in conjunction with grep in order to isolate issues to specific strings such as ADPlugin. If you choose to use -USR2 for debugging then the logs will get written into the /var/log/system.log file.
To disable verbose logging you can just restart the Directory Services daemon if you are in -USR1 or if you are using -USR2 debugging information will automatically stop writing to the log after 5 minutes.