Analysis of Apple Unified Logs: Quarantine Edition [Entry 5] – Login Inception!? Yes! – Local Logins!

April 28, 2020 in logs, macos, analysis

Local logins are created when an already logged in user opens a Terminal window. Each terminal window is a separate ‘login’ process. If you have six Terminal windows (or tabs) open, you have six ‘login’ processes.

In the last article, I showed how you can find these processes using other log types. Let’s see what local logins look like in unified logs. Trying to create a query from these, I ran into an issue trying to filter for the ‘login’ process which makes a great learning example.

If I try to use ‘processImagePath’ I get lots of unnecessary entries from ‘loginwindow’ or any other process that might have ‘login’ in the name. This is because the process that we see in the default ‘log’ output is actually part of a path as the field ‘processImagePath’ suggests.

log show --predicate 'processImagePath contains "login"'

We can use a different output style to see these paths. I used JSON for the output in the screenshot below.

log show --predicate 'process contains "login"' --style json

To filter specifically for the ‘login’ process, I will use ‘process’ instead of ‘processImagePath’ which will just filter on the process name. As an example, I changed ‘contains’ to ‘=’ in the first command line to show it is looking for just the term ‘login’. This shows no results due to using ‘processImagePath’ instead of ‘process’.

log show --predicate 'process = "login"'

Getting back to those ‘login’ processes, I created the query below. While not perfect it does show some interesting items.

log show --info --predicate '(processImagePath contains "opendirectory" and eventMessage contains "Client:") or process = "login"'

In this test, I just opened a new tab in Terminal and performed a few commands.

The query output shows the ‘login’ process as well as a few ‘open directory’ entries. Not all of these are related to this Terminal action, but these can be visually filtered out by using process IDs (40881, 40882). While this does show a new Terminal window opening via the ‘login’ process we also see the exiting action for ‘zsh’ and ‘login’.

Unfortunately, I have found that these particular ‘opendirectoryd’ processes will expire in a very short time period (~90 minutes) therefore I might revert back to other logs to extract this information as show in this syslog output.

Can you really have ‘login’ inception? Yes! (I’m using the ‘login’ command here to login to various user accounts in the same shell. 🤪)

Analysis of Apple Unified Logs: Quarantine Edition [Entry 4] – It’s Login Week!

April 26, 2020 in logs, macos, analysis

No one can find flour or yeast anyway! 😆

This week is all about system logins! On the system (via password, TouchID, or Apple Watch), local logins using Terminal, and remote logins over SSH and Screen Sharing. There are many ways of accessing a macOS system, certainly this is not all inclusive but should cover many investigative scenarios.

Let’s start with Login Window logins. These are the types of user logins that I like to call “hands-on-keyboard” at a GUI login screen. You are looking at a Mac system and log in.

The complexity of these logins has changed quite a bit over the last few years with the introduction of TouchID and Auto Login with the Apple Watch.

First, let’s review what these log entries used to look like. In reality, many of these entries still exist in these logs. Just a reminder here that there are other logs on the system that you may still need to review! These particular logs can be found in /private/var/log/system.log (and archived versions) as well as the Apple System Logs (ASL) in the /private/var/log/asl directory.

Starting with system.log and its archived versions, I’m looking for entries that contain the string “_PROCESS”. I used ‘gzcat’ to extract the messages from the gzip archives and ‘cat’ for the current system.log file.

gzcat system.log.{1..0}.gz | grep _PROCESS && cat system.log | grep _PROCESS

A USER_PROCESS is a logon while DEAD_PROCESS is a logoff. These are tied together with a process ID that follows it. The facilities that record the message tell what type of login it is.

loginwindow – These are the “hands-on-keyboard” logins that I’ll be talking about in this particular post.
login – These logins are local logins, you’ll see these with each Terminal window you have open.
sessionlogoutd – Pair these with the loginwindow login entries. This is the logout.
Not shown in the screenshot is remote logins via SSH. These have the ‘sshd’ facility.

These entries don’t provide a whole lot of context. They don’t tell me which user is logging in or how (Password, TouchID, or Apple Watch)

Another log that contains similar information are the Apple System Logs (ASL). In the example, I’ve parsed these out using ‘syslog’ with a raw output format and UTC timestamps. Note I’m only showing the first three entries as these are fairly verbose. The only additional context these provide is the user logging on and where they are coming from if it is a remote login. (The raw output format is needed to see this, otherwise the output looks similar to system.log entries.)

syslog -F raw -T UTC | grep "_PROCESS"

The third place to look for these entries is the Basic Security Module (BSM) Audit trail logs. These can be parsed with ‘praudit’. A single login entry is show below, no one likes looking at these logs due to their multi-token format.

One good thing about these is that they seemed to be retained longer than system.log and ASL which has been seemingly cut down in Catalina (10.15) to about 3 days from ~7 days in system.log and ~365 days in ASL for login entries. (Oddly, the ASL Expire times are a year out as they were in previous macOS versions. 🤷🏻‍♀️)

These are all great places to look but we need more context. To the Unified Logs! The problem with unified logs is that they can be very verbose, just looking at my ‘loginwindow’ process entries for a day, I have about 20k! There is no way I’m going to scroll through and attempt to interpret each entry. I need to filter for specific entries. I’ve come up with a few useful queries to find specific pieces of information.

The first is looking for messages that contain ‘com.apple.sessionagent.screenIs’ string. This is going to show if the system is locked or unlocked, and which user is currently logged in with their user ID (UID). These are not technically logins since the user is already logged in but are useful for telling if the screen is locked or not

com.apple.sessionagent.screenIsLocked = Screen is Locked
com.apple.sessionagent.screenIsUnlocked = Screen is Unlocked

log show --predicate 'eventMessage contains "com.apple.sessionagent.screenIs"'

To determine when the user did a true login (versus just a screen unlock) we can look for com.apple.sessionDidLogin in the message while specifically looking at the ‘loginwindow’ process.

log show --predicate 'processImagePath contains "loginwindow" and eventMessage contains "com.apple.sessionDidLogin"'

I really like the messages associated with ‘SessionAgentNotificationCenter’. They are easy to interpret which is why I chose them for these examples. I created a broader query to get more details about these login sessions to include the following entries:

com.apple.system.loginwindow.shutdownInitiated – User chose to shutdown system
com.apple.system.loginwindow.logoutcancelled – User canceled the shutdown (or restart or logoff)
com.apple.system.loginwindow.restartinitiated – User chose to restart system

log show --predicate 'eventMessage contains "com.apple.system.loginwindow" and eventMessage contains "SessionAgentNotificationCenter"'

You might notice a couple UID’s in these examples (501 and 502). This is me going back and forth between accounts using Fast User Switching which can be filtered for by using ‘com.apple.fastUserSwitchBegin’.

Keeping track of what we have so far using ‘SessionAgentNotificationCenter’

Screen Lock/Unlock Status
User Logons
User Logoff
Restarts (w/UID)
Shutdown (w/UID)
Fast User Switching
Canceled Restart/Shutdown/Logoff

To get all these ‘SessionAgentNotificationCenter’ messages try using this query:

log show --predicate 'eventMessage contains "SessionAgentNotificationCenter"'

Password, TouchID, or Apple Watch?

So many loginwindow logins but which type! Is it a normal password login, using TouchID, or Auto Unlock using their Apple Watch? I find the messages that contain ‘LWScreenLockAuthentication’ are good for this. I’ve also added the strings ‘| Verifying’ and ‘| Using’ to filter it further.

log show --predicate 'eventMessage contains "LWScreenLockAuthentication" and (eventMessage contains "| Verifying" or eventMessage contains "| Using")'

The screenshot above contains the three different types of logins.

Regular Password:

“Verifying using PAM configuration screensaver”

TouchID:

“Using localAuthentication hints”
“Using hint-provided username oompa”
“Verifying using PAM configuration screensaver_la”

Auto Unlock with Apple Watch:

“Using continuity hints”
“Using hint-provided username oompa”
“Verifying using PAM configuration screensaver_aks”

To get more detail I want to look at messages for ‘LWDefaultScreenLockUI’. I’ve combined these entries together in a long query looking for specific keywords.

log show --predicate 'eventMessage contains "LWDefaultScreenLockUI" and (eventMessage contains "authSuccess" or eventMessage contains "authFailWithMessage" or eventMessage contains "loginPressed" or eventMessage contains "authBegan" or eventMessage contains "preLoad")'

The keyword ‘preload’ provides us some metadata about the system.

fmmEnabled – Find my Mac is Enabled
fusEnabled – Fast User Switching is Enabled
The number of user accounts are on the system

The next set shows if the login was successful or not.

loginPressed – Password Attempt Number (Attempt #: ?)
- If someone is attempting to brute force via typing in passwords you’ll see the number of attempts tick up.
authBegan – Begin Authentication
authFailWithMessage – Authentication Failed
authSuccess – Authentication Successful

I bet you thought login entries would be easy! Coming up this week are local logins and remote logins via SSH and Screen Sharing.

Analysis of Apple Unified Logs: Quarantine Edition [Entry 3] – Playing in the Sandbox, Enumerating Files and Directories

April 24, 2020 in macos, analysis, logs

While I’ve been researching various queries with these unified logs, I’ve noticed some peculiar but forensically useful entries. I have found many of these entries to be created when I’m browsing directories via Finder. However, they don’t appear to be logged on every directory I browse. Many of these entries also appear to be associated with particular applications/services.

This query is searching for the ‘kernel’ in the process path and ‘Sandbox’ in the sender path. To filter even further, I’ve added a keyword search for ‘file-read-xattr’ in the event message area.

This query limits the search to the last 10 minutes and during my testing these are directories I specifically browsed to within Finder. Again, I’ll note that I was able to browse to other directories using Finder but these were not logged for whatever reason.

log show --last 10m --predicate 'processImagePath contains "kernel" and senderImagePath contains "Sandbox" and eventMessage contains "file-read-xattr"'

This first example shows entries associated with the ‘garcon’ process which is associated with DropBox. I’m using TaskExplorer here from Objective-See to review information about this process.

These entries are not specific to Dropbox. Looking at my own logs, I also have entries for other applications and system services:

App Store
Microsoft Excel
Microsoft Word
MusicCacheExtens[ion] (Long process names get truncated)
TVCacheExtension
TextEdit
com.apple.CloudP[hotosConfiguration?]
mediaanalysisd

To look for the Microsoft specific entries, I added another keyword to the query to search the message area for ‘Microsoft’. This should cover all Microsoft products. While the listed directories were directories I recall browsing to, some of these documents I did not specifically open (over and over again) at these times. The application may somehow cache some of these document paths. I did in fact open these documents, just not during these particular times.

log show --predicate 'processImagePath contains "kernel" and senderImagePath contains "Sandbox" and eventMessage contains "file-read-xattr" and eventMessage contains "Microsoft"'

The last example shows TextEdit entries. This may look like I opened or accessed this Zoom chat transcript three times today (4/23/2020), but I sure didn’t. I did however open it up in the past. Again, this appears to be cached somewhere to make it appear that it has been opened.

log show --last 10h --predicate 'processImagePath contains "kernel" and senderImagePath contains "Sandbox" and eventMessage contains "file-read-xattr" and eventMessage contains "TextEdit"'

These entries certainly need to be researched further. Some entries appear to be associated with specific user interactions while others seem to be logged at random due to how an application may work. It is worth noting these entries are a log type of ‘Error’. They may not always be available. (Some are of type ‘Default’ as well).

While the timestamps may not quite match up to specific usage, these entries may still be useful in investigations to show directory contents or documents previously opened.

Analysis of Apple Unified Logs: Quarantine Edition [Entry 2] – sudo make me a sandwich

April 22, 2020 in macos, analysis, logs

The first item in the Unified Logs we will take a look at is a relatively simple one – evidence of the ‘sudo’ command.

In this example I’m attempting to view all the log types (including default and info) for the last day (--last 1d). The search/filter (--predicate) I’m using is looking for the ‘sudo’ process. This column highlighted in pink text.

log show --info --debug --last 1d --predicate 'process == "sudo"'

This has many entries not immediately useful to me, I can create a more specific query to filter the noise out. I’ve removed the arguments for debug and info messages as they do not appear to be needed for this query (they may for others so don’t forget about them!). To get just the entries of interest, I added a keyword search for ‘TTY=’ in the message column (eventMessage).

log show --last 1d --predicate 'process == "sudo" and eventMessage contains "TTY="'

Another technique to look at just the entries associated with a specific use of ‘sudo’ can be to filter by the Process ID (PID) by using ‘processID’. (I replaced info/debug message in the query not because its necessary but purely because its muscle memory for me to do so!)

log show --info --debug --last 1d --predicate 'processID == 26220

I tried to get a bit creative with ‘sudo’, so I incorrectly put a password in (twice) while trying to use ‘sudo -s’. I then put in the correct password. Note, I’m using the ‘last’ argument to only look at events in the last 20 minutes. Very useful if you are trying to research a certain scenario without having to scroll through millions of log entries!

log show --last 20m --info --debug --predicate 'process == "sudo" and eventMessage contains "TTY="'

While we’re here, it would be a shame not to take a quick look at ‘su’ as well. Oops, looks like I got the password wrong while doing a ‘su janedoe’ three times before finally getting it right.

I’ve changed this query a tiny bit. The process was changed to ‘su’ instead of ‘sudo’ and the keyword in the message from changed from ‘TTY=’ to ‘tty’ to capture these entries.

log show --last 20m --info --debug --predicate 'process == "su" and eventMessage contains "tty"'

Finally let’s get a query to find all the relevant ‘sudo’ and ‘su’ commands. I created a slightly more complex query that combines searching for two different processes (sudo and su) while still filtering for ‘tty’ in the message.

log show --last 20m --info --debug --predicate '(process == "su" or process == "sudo") and eventMessage contains "tty"'

To make query slicker , we can use ‘beginswith’ to just look for ‘su’ in the two processes.

log show --last 30m --info --debug --predicate 'process beginswith "su" and eventMessage contains "tty"'

And one last one, because I know you NEED to know!

Big thanks to one of my favorite comics for the classic content, these never get old! XKCD by Randall Munroe

Analysis of Apple Unified Logs: Quarantine Edition [Entry 1] – Converting Log Archive Files on 10.15 (Catalina)

April 20, 2020 in logs, macos

Please review this post first as it contains an update to this post. Keeping the contents of this blog intact for reference purposes only.

Apple introduce Unified Logging many years ago in 10.12 and has constantly been changing it since its introduction. My main problem is usually using the ‘log’ utility. It has changed over time and those changes are not documented nor is the current documentation adequate in many cases.

My most recent adventure using ‘log’ came when I was running through my course image to create a logarchive bundle from a dead system image. This particular system was running 10.13.1 and will have to be read from whatever macOS the student is running at the time. Silly me for thinking that ‘log’ would always “just work”™️.

When students upgraded to 10.14.x, they could still create the log archive via the manual process of doing a recursive copy of the /private/var/db/diagnostics and /private/var/db/uuidtext directories into a *.logarchive directory bundle. Works great! Even works (worked?) on iOS devices! On 10.14.x systems we have “force” it into the proper format but it was readable by ‘log’ and the timestamps appeared correct.

When 10.15 came out, this changed. Attempting to create and read the same data produces a corruption error. There is no option to “force” it.

I have been racking my brain and researching this on and off since Catalina was introduced. How the heck can I make this older logarchive readable using a newer versions of macOS?

Comparing the older and newer logarchive formats, they are nearly the same except for a few items. One difference I focused on was the key OSArchiveVersion in the Info.plist. On 10.14 and 10.15 they are on version 4, while on 10.13 they were on version 3. (Note: Doing a recursive copy from a dead image does not create this Info.plist file in the root of the logarchive bundle.)

In my first test, I simply added an Info.plist file to the root of the logarchive bundle with one key, OSArchiveVersion. For the value I tried 4 – why not just give it what it wants. (This testing was done on 10.15.3).

Great, it parses! However the timestamps are not quite right. I’m lucky to have a dataset that I’m familiar with and have a course labs with specific log entries and their timestamps to validate the conversion. This particular entry I’ve blogged about before – this entry should have the timestamp 2018-02-26 01:49:08.719840+0000. You can see it is only off by a smidge, what gives? These things bother me, so I decided to dive deeper.

Something else is part of this conversion. (I knew it would have been too easy to just change a plist value!)

Next, I changed the value of OSArchiveVersion to a 3. In theory, I hoped to upgrade it to version 4 but still got the same wrong timestamp. I was also not even offered the “force” option. (I really should have known it would have been too easy to just change a plist value!)

In a moment of ‘why not, let me just try this for fun’, I changed the value to 2. …and it actually WORKED! It freaking worked! I had to force it and the timestamps matched up with my original values.

I would love to know why this worked. It makes no logical sense to me.

What happens if I just go straight to version 2 for OSArchiveVersion? It also worked!

A quick command to get this done:

/usr/libexec/PlistBuddy -c "Add :OSArchiveVersion integer 2" galaga.logarchive/Info.plist

What changes in this “forced” conversion?

I created a new copy of the logarchive bundle and put the Info.plist with OSArchiveVersion = 2. Using one of my favorite file system monitoring tools, fsmon [https://github.com/nowsecure/fsmon]. I was able to monitor what the --force flag changed in the logarchive bundle.

It deletes the timesync directory (and the *.timesync file within) then creates it again with a different timesync file. Also as expected the Info.plist changes from 2 to 4.

What the heck are these timesync files? Not entirely sure, they are binary files that obviously has some sort of time syncing purpose which is why the timestamps now match up. Perhaps I will dig into these another time.

Afterthoughts

I’m not sure why 10.15 refuses to convert log archives as 10.14 did. Perhaps it is a bug, maybe it is intentional but it sure does make doing forensics difficult. I’m sure this will cause problems with newer versions of macOS as well as other platforms. I’ve heard the same problem exists with iOS, which again will likely be another blog entry when I get to testing iOS specifically.

It does however bring up a good lesson…do not implicitly trust timestamps. I’ll state this over and over until I can get people to test these things. I had it easy with this one because I had known test data – but that doesn’t work so well with random case data.

Below is the mapping of macOS version to Unified Logs Archiver versions (found in the Info.plist files while doing a ‘log collect’ command on a live system.) There are many empty spots – I have no idea if it will help or not but I tried to document it here. If you can help fill it in, I would be grateful please contact me. (Seems most folks update to the latest!)