krypted.com

Tiny Deathstars of Foulness

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!

July 26th, 2017

Posted In: Mac OS X, Mac OS X Server, Mac Security

Tags: , , , , ,

This is the first page of a 5 page piece I just finished writing for MacTech. After the last episode of the MacAdmins podcast though, I wanted to go ahead and get some of the information out there. For a much more detailed analysis, check out MacTech! 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

March 26th, 2017

Posted In: Mac OS X, Mac OS X Server

Tags: , , , , , ,

Meraki has a syslog option. To configure a Meraki to push logs to a syslog server, open your Meraki Dashboard and click on a device. From there, click on “Alerts & administration”. Screen Shot 2014-04-12 at 8.29.16 PM At the “Alerts & administration” page scroll down to the Logging section. Click on the “Add a syslog server” link and type the IP address of your syslog servers name or IP. Put the port number into the Port field. Choose what types of events to export. This could be Event Log, Flows or URLs, where:
  • Event Log: The messages from the dashboard under Monitor > Event log.
  • Flows: Inbound and outbound traffic flows generate syslog messages that include the source and destination and port numbers.
  • URL: HTTP GET requests generate syslog entries.
Note that you can direct each type of traffic to a different syslog server.

April 16th, 2014

Posted In: cloud, Mac Security, Network Infrastructure

Tags: , , , , , , , , ,

When bash scripting, a useful command is logger. The logger command allows you to “make entries in the system log.” When using the logger command, you can write to your own entries to the system log. To show how this command works, we’re going to open two terminal windows, preferably side-by-side. In one window, we’re going to look at the output of the system.log file interactively using the tail command with the -f option tail -f /private/var/log/system.log In the other window, we’re going to simply enter the logger command followed by the word frogger: logger frogger This will show you an entry similar to the following: Jun 3 00:34:44 ce.pretendco.com krypted[77276]: frogger Congrats, you’ve successfully written your own log entry into the system log. Now that you’ve done that, go ahead and press the up arrow on your keyboard to see the line again and then hit enter. You’ll then see the same line, with the pid more than likely incremented up by one. The pid is the process id of the logger command you just ran. If you run ps you’ll note that the pid is no longer in use. Next, we’ll create a text file called froggerlog in our home directory, populating it with just the string: mylogdata. This is meant to emulate having written some data into a log file. We’ll do so using the echo command: echo mylogdata > froggerlog Now that we have a file, use the -f option to include the contents of the file into the system.log, specifying the path to the file: logger -f ~/froggerlog You will then see something like the following, with your mylogdata string in it: Jun 3 00:37:24 ce.pretendco.com krypted[77279]: mylogdata Using that structure, you can write data into a file and then later dump that data into the log, so as not to fill up the system.log file with tons of random data as it happens. Or you can write directly into the log as needed. It’s good to have choices. The -i option is used to include the pid for the logger process in each line. But if you go back and add a second line of data into your log file, and re-run the logger command against that file you’ll notice that the pid is included with each line the same no matter whether you use the -i or not, making the -i unnecessary. You will also note that consecutive rows with the same information simply say — last message repeated 1 time —. This helps to keep log files a bit more trim than they otherwise might be if you have, say, 10,000 lines with the same content: Jun 3 00:50:57 ce.pretendco.com krypted[588]: mylogdata Jun 3 00:51:17 ce.pretendco.com krypted[588]: 1234 Jun 3 00:51:17 --- last message repeated 1 time --- Jun 3 00:51:17 ce.pretendco.com krypted[588]: abc Now, you might find it difficult to see only the pertinent lines to your script. Use the -t option to tag a line, followed by the tag. For example, let’s add myscript into our lines, continuing to write into the system.log using the froggerlog file from earlier: logger -t myscript -f ~/froggerlog Note the output contains the myscript tag in front of the pid, in place of the username you were writing entries as: Jun 3 00:56:28 ce.pretendco.com myscript[601]: mylogdata Jun 3 00:56:28 ce.pretendco.com myscript[601]: 1234 Jun 3 00:56:28 --- last message repeated 1 time --- Jun 3 00:56:28 ce.pretendco.com myscript[601]: abc Messages can be written at various priorities. To set the priority of your entries, use the -p option. After that enter the priority as an integer, using the following:
  • Alert: Level 1
  • Error: Level 3
  • Warning: Level 4
  • Notice: Level 5
  • Info: Level 6
  • Debug: Level 7
For example, to write an alert entry (everyone should see this): logger -t myscript -f ~/froggerlog -p alert To write a debug log: logger -t myscript -f ~/froggerlog -p debug The alert log is shown but the debug is not. Levels 5-7 are not displayed using a tail of system.log. If you need to verify success or failure of entries, note that logger exits 0 on success but not when an error is encountered. If you’d like to output entries to standard error, you can do so by adding the -s option as well.

June 3rd, 2013

Posted In: Mac OS X

Tags: , , , , , , ,