![\"\"](\"https:\/\/dreness.com\/blog\/wp-content\/uploads\/2021\/03\/image.png\")
<\/a>We know that macOS logs<\/a> quite a bit – so much, in fact, that the hard part about using logs is achiving a favorable signal to noise ratio. It’s usually much easier to select signal than it is to filter noise – especially if you already know something about what you’re looking for. For this case study we can get an initial lead, but even if we couldn’t, our strategy will still work, maybe with an extra iteration or two.<\/p>\n\n\n\n The If I didn’t already know that \u2026 but that output is not so easy to read. Let’s use Nope, Before we continue, as our Now when we run Ok, putting it all together:<\/p>\n\n\n\n Definitely more legible, but\u2026 the above represents a single log event. We can do better. In this case that’s probably close enough, and you’ll probably see stuff about keys being written. Let’s pretend it’s still too noisy. What if we had a way to see only the different kinds<\/em> of messages without the dynamic parts of each. We do! Just ask for There is a complication, though. If you append There’s still one more problem (this is the last one, honest). Let’s have a look at the You may have noticed I don’t like the first method because it doesn’t stick – the next time a Note that when targeting a subsystem, we also need to enable persisting<\/em> of the debug-level messages, otherwise those messages will briefly pass through the in-memory ring buffer before being forgotten.<\/p>\n\n\n\n We can now finally achieve a good summary of log activity by simply counting the unique instances of Ok, Now we just use the If you came to learn how to claw law blogs from os_log’s sprawling maw, get on outta here Bob Loblaw – the rest is about hotkeys.<\/p>\n\n\n\n There are at least two different representations of hotkeys you might encounter in NSUserDefaults. As an example of \u2026 then change the spotlight hotkey in system preferences, then run<\/p>\n\n\n\n \u2026 then diff these plists:<\/p>\n\n\n\n Looking at the whole file, it seems like maybe the different functions that can be assigned hotkeys are represented here by a numeric ID, and I found a neat app called Key Codes<\/a> that can be used to understand how the key code values work. For example, if I:<\/p>\n\n\n\n \u2026 we see that the codes for command-space are Here’s a method to find where any given NSUserDefault setting is persisted. This might help if you’re trying to write a script to get or set that setting. As a bonus, this post details a reusable strategy for withstanding the … Continue reading log<\/code> man page tells us we can match log events in lots of ways, including by process – but which process should we look upon?<\/p>\n\n\n\nandre@boop ~ % apropos prefs\nCPAN::Distroprefs(3) - -- read and match distroprefs\ncfprefsd(8) - defaults server<\/code><\/pre>\n\n\n\ncfprefsd<\/code> is our target, I would read the cfprefsd<\/code> man page (because all apropos<\/code> results are man pages). We could start by listening to all of cfprefsd<\/code> by running:<\/p>\n\n\n\nlog stream --debug --predicate 'process == \"cfprefsd\"'<\/code><\/pre>\n\n\n\nlog<\/code>‘s ndjson<\/code> output style so we can view it with jq<\/code>, but first let’s make sure the json output is clean enough (foreshadowing!)<\/p>\n\n\n\nandre@boop ~ % log stream --predicate 'process == \"cfprefsd\"' --style ndjson --debug \nFiltering the log data using \"process == \"cfprefsd\"\"\n{\"traceID\":36107480853643780,\"eventMessage\":\"Process 68 (UserEventAgent)\n...<\/code><\/pre>\n\n\n\njq<\/code> won’t like that, so let’s filter the log<\/code> output with egrep --line-buffered '^{'<\/code> to only pass lines starting with {<\/code> to jq<\/code>. Don’t forget --line-buffered<\/code>, otherwise grep<\/code> ‘helps’ by saving a tiny fraction of computer by showing output less often, which grep<\/code> believes is appropriate because it doesn’t think there’s a human watching (because its stdout isn’t connected to a terminal, it is connected to jq<\/code>).<\/p>\n\n\n\nlog<\/code> command is becomming lengthy, let’s clean up a little by setting some common options in ~\/.logrc<\/code> (described in the log<\/code> man page). Here’s a command to populate ~\/.logrc<\/code> with some settings useful for the task at hand:<\/p>\n\n\n\ncat > ~\/.logrc <<EOF\nstream:\n --debug\n --style ndjson\n\npredicate:\n prefs 'process contains \"cfprefsd\"'\nEOF<\/code><\/pre>\n\n\n\nlog stream --predicate prefs<\/code>, log<\/code> behaves as though we typed:<\/p>\n\n\n\nlog stream --debug --style ndjson --predicate 'process CONTAINS \"cfprefsd\"<\/code><\/p>\n\n\n\nandre@boop ~ % log stream --predicate prefs | egrep --line-buffered '^{' | jq \n{\n \"traceID\": 36107480853643780,\n \"eventMessage\": \"Process 1347 (ContextStoreAgent) sent a request related to { ContextStoreAgent, user: andre, kCFPreferencesAnyHost, \/Users\/andre\/Library\/Preferences\/ContextStoreAgent.plist, managed: 0 } (0x7fe2c19057d0)\",\n \"eventType\": \"logEvent\",\n \"source\": null,\n \"formatString\": \"Process %{public}d (%{public}s) sent a request related to { %{public}s, user: %{public}s, %{public}s, %{public}s, managed: %d } (%p)\",\n \"activityIdentifier\": 7609380,\n \"subsystem\": \"com.apple.defaults\",\n \"category\": \"cfprefsd\",\n \"threadID\": 5781976,\n \"senderImageUUID\": \"2A0E160E-9EE6-3B23-8832-6979A16EC250\",\n \"backtrace\": {\n \"frames\": [\n {\n \"imageOffset\": 1698619,\n \"imageUUID\": \"2A0E160E-9EE6-3B23-8832-6979A16EC250\"\n }\n ]\n },\n \"bootUUID\": \"\",\n \"processImagePath\": \"\/usr\/sbin\/cfprefsd\",\n \"timestamp\": \"2021-03-20 18:30:44.017031-0700\",\n \"senderImagePath\": \"\/System\/Library\/Frameworks\/CoreFoundation.framework\/Versions\/A\/CoreFoundation\",\n \"machTimestamp\": 585248221966448,\n \"messageType\": \"Debug\",\n \"processImageUUID\": \"5E5EBAAF-AA0E-38E1-B19A-07FB2FB8ECED\",\n \"processID\": 406,\n \"senderProgramCounter\": 1698619,\n \"parentActivityIdentifier\": 0,\n \"timezoneName\": \"\"\n}\n...<\/code><\/pre>\n\n\n\neventMessage<\/code> has the interesting info, so let’s look only at that by using a jq<\/code> filter: '. | .eventMessage'<\/code><\/p>\n\n\n\nandre@boop ~ % log stream --predicate prefs \\\n| egrep --line-buffered '^{' | jq '. | .eventMessage'\n\"Process 1347 (ContextStoreAgent) sent a request related to { ContextStoreAgent, user: andre, kCFPreferencesAnyHost, \/Users\/andre\/Library\/Preferences\/ContextStoreAgent.plist, managed: 0 } (0x7fe2c19057d0)\"\n\"Process 1347 (ContextStoreAgent) sent a request related to { ContextStoreAgent, user: andre, kCFPreferencesAnyHost, \/Users\/andre\/Library\/Preferences\/ContextStoreAgent.plist, managed: 0 } (0x7fe2c19057d0)\"\n\"Process 97346 (PerfPowerServices) sent a request related to { com.apple.powerlogd, user: kCFPreferencesAnyUser, kCFPreferencesCurrentHost, \/Library\/Preferences\/com.apple.powerlogd.plist, managed: 0 } (0x7fb3ee304a30)\"<\/code><\/pre>\n\n\n\nformatString<\/code> instead of eventMessage<\/code>, then sort | uniq<\/code>.<\/p>\n\n\n\nsort | uniq<\/code> to the previous pipeline and run it, you will see no output – this is because both sort<\/code> and unique<\/code> can’t run in stream mode; they have to receive all the input before they can do their job. If you simply control-c to terminate log<\/code>, this seems to cause the in-flight log data to become malformed some time before it reaches jq<\/code>. Instead of figuring that out, I opted to forgo log stream<\/code> in favor of log show<\/code>, because log show<\/code> doesn’t run forever, so I won’t have to control-c it and have broken pipes.<\/p>\n\n\n\nlogd<\/code> man page:<\/p>\n\n\n\n All processes that use os_log(3) share pages of memory with logd and\n append entries to them. logd reads pages and combines and compresses\n this data. Depending on configured policies, it keeps them in a local\n ring buffer or writes them out to persistent storage.\n\n { logd }\n | `---> [ buffer ] ----.\n | ,`---> { log show }\n `---> [ data store ] -'<\/code><\/pre>\n\n\n\n\"messageType\": \"Debug\",<\/code> in the previous output, indicating that the messages of interest are logged at the debug level. When you pass the --debug<\/code> option to log stream<\/code>, log<\/code> temporarily activates debug-level messages so you can see them as they happen, and then disables debug mode when you control-c. In other words, switching to log show<\/code> won’t work until we enable debug-level messages some other way. There are at least two ways to do this according to the log<\/code> man page:<\/p>\n\n\n\n# change the global log level to debug\nsudo log config --mode \"level: debug\"\n\n# ... or set a specific subsystem to debug\nsudo log config --subsystem 'com.apple.defaults' --mode level:debug --mode persist:debug<\/code><\/pre>\n\n\n\nlog stream<\/code> command exits, log<\/code> helpfully disables debug-level messages, even if they were enabled before running log stream<\/code>.<\/p>\n\n\n\nformatString<\/code> values.<\/p>\n\n\n\nandre@boop % log show --last 10m --predicate prefs \\\n| egrep --line-buffered '^{' | jq '. | .formatString' > fstrings\n\nandre@boop % cat fstrings | sort | uniq -c | sort -n\n 1 null\n 32 \"Data for { %@, %@ } was purged due to memory pressure\"\n 32 \"no cache for { %{public}s, %{public}s, %{public}s, %{public}s, managed: %d }, loading from %{public}s\"\n 38 \"wrote file %{public}s\"\n 42 \"Notifying observers of { %{public}s, %{public}s, %{public}s, %{public}s, managed: %d }\"\n 82 \"Process %{public}d (%{public}s) wrote the key(s) %{public}s in { %{public}s, %{public}s, %{public}s, %{public}s, managed: %d }\"\n 90 \"Process %{public}d (%{public}s) read data for { %{public}s, %{public}s, %{public}s, %{public}s, managed: %d }, backed by %{public}s\"\n 416 \"Process %{public}d (%{public}s) sent a request related to { %{public}s, user: %{public}s, %{public}s, %{public}s, managed: %d } (%p)\"\n 482 \"Couldn't %{public}s %{private}s due to %{public}s\"<\/code><\/pre>\n\n\n\nwrote file ...<\/code> and process ... wrote the key(s) ...<\/code> look promising for this sample case. Let’s update our .logrc<\/code> file to add a stanza for show<\/code>. Also change the prefs<\/code> predicate macro to specify category = \"cfprefsd\"<\/code> instead of process<\/code> (not strictly required, but good to use categories when possible). Lastly, add another predicate macro called keys<\/code> to conjure a refined version of the prefs<\/code> search that will only return events that represent writes to NSUserDefaults.<\/p>\n\n\n\nshow:\n --style compact\n --color always\n --last 1h\n --debug\n --style ndjson\n\nstream:\n --debug\n --style ndjson\n\npredicate:\n prefs 'category = \"cfprefsd\"' \n keys 'category = \"cfprefsd\" and eventMessage contains \"wrote\"'<\/code><\/pre>\n\n\n\nkeys<\/code> predicate macro and clean the output with egrep<\/code> and jq<\/code> like before:<\/p>\n\n\n\nandre@boop ~ % log show --last 10m --predicate keys \\\n | egrep --line-buffered '^{' | jq '. | .eventMessage'\n...\n\"wrote file \/Users\/andre\/Library\/Preferences\/com.apple.symbolichotkeys.plist\"\n...<\/code><\/pre>\n\n\n\n
\n\n\n\nNSUserKeyEquivalents<\/code> (as in defaults find NSUserKeyEquivalents<\/code>) is pretty self-explanatory, but there’s also AppleSymbolicHotKeys<\/code> which is somewhat more opaque.<\/p>\n\n\n\nAppleSymbolicHotKeys<\/code>, run<\/p>\n\n\n\ndefaults find AppleSymbolicHotKeys > hotkey1.plist<\/code><\/pre>\n\n\n\ndefaults find AppleSymbolicHotKeys > hotkey2.plist<\/code><\/pre>\n\n\n\n***************\n*** 460,474 ****\n };\n };\n 64 = {\n enabled = 1;\n value = {\n parameters = (\n! 32,\n! 49,\n! 1048576\n );\n type = standard;\n };\n };\n 65 = {\n enabled = 1;\n--- 460,474 ----\n };\n };\n 64 = {\n enabled = 1;\n value = {\n parameters = (\n! 107,\n! 40,\n! 786432\n );\n type = standard;\n };\n };\n 65 = {\n enabled = 1;<\/code><\/pre>\n\n\n\n64<\/code> is the one for “show spotlight search”. The parameter values are key codes.<\/p>\n\n\n\n32, 49, 1048576<\/code> – note especially that the stored value does not include the device-specific aspect of the modifier (0x8<\/code>). This matches what is shown in the diff output above from hotkey1.plist<\/code><\/p>\n\n\n\n<\/a>