Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Are ES_EVENT_TYPE_NOTIFY_WRITE events triggered by iCloud (bird etc) or any better way to log them? #7

Open
luckman212 opened this issue May 26, 2021 · 6 comments

Comments

@luckman212
Copy link

I've been trying to use FileMonitor to track down a really annoying and elusive bug with 0-byte files (files getting spuriously emptied and losing their data). I'm trying to trigger this bug while FileMonitor is running, and I'm seeing some weird behavior where it seems as if iCloud's daemons (bird and whatever other daemons run in the background and handle iCloud file sync) are able to modify the filesystem right under the nose of tools like FileMonitor.

Here's a POC script for testing - requires jq (brew install jq)

poor-mans-fsusage.sh

#!/usr/bin/env bash

logfile="$HOME/Desktop/FileMonitor.log"
re="^$HOME/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt"
e_types='[
"ES_EVENT_TYPE_NOTIFY_CLONE",
"ES_EVENT_TYPE_NOTIFY_CREATE",
"ES_EVENT_TYPE_NOTIFY_FCNTL",
"ES_EVENT_TYPE_NOTIFY_RENAME",
"ES_EVENT_TYPE_NOTIFY_SETACL",
"ES_EVENT_TYPE_NOTIFY_SETATTRLIST",
"ES_EVENT_TYPE_NOTIFY_SETEXTATTR",
"ES_EVENT_TYPE_NOTIFY_SETFLAGS",
"ES_EVENT_TYPE_NOTIFY_SETMODE",
"ES_EVENT_TYPE_NOTIFY_SETOWNER",
"ES_EVENT_TYPE_NOTIFY_SETTIME",
"ES_EVENT_TYPE_NOTIFY_TRUNCATE",
"ES_EVENT_TYPE_NOTIFY_UNLINK",
"ES_EVENT_TYPE_NOTIFY_WRITE"
]'

echo "% logging started (file: $logfile)" | tee -a "$logfile"
echo "% using regex: $re" | tee -a "$logfile"

sudo /Applications/FileMonitor.app/Contents/MacOS/FileMonitor -pretty |
jq --raw-output --unbuffered --argjson e "$e_types" --arg re "$re" '
  select(.event? | IN($e[])) |
  select(.file.destination?|match($re)) |
  [ .event, .file.process.name, .file.destination ] |
  @tsv' |
tee -a "$logfile"

Running this script and then creating/updating the xyzzy.txt file at the root of iCloud Drive with common tools like Sublime Text, echo foo >>xyzzy.txt or rm xyzzy.txt produces output like this:

$ poor_mans_fsusage.sh
% logging started (file: /Users/luke/Desktop/FileMonitor.log)
% using regex: ^/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_CREATE	sublime_text	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_WRITE	sublime_text	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_WRITE	bash	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_UNLINK	rm	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_CREATE	touch	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt

However, if I open this file up on my iPhone (using Files.app) and modify it there, a strange thing happens. No ES_EVENT_TYPE_NOTIFY_WRITE events are seen. Yet the file somehow gets updated. It appears that maybe there is some sort of atomic saving going on (temp file saving, moving (renaming) the original, replacing etc. But I can't be sure. Here's a sample of the output:

ES_EVENT_TYPE_NOTIFY_RENAME	bird	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_RENAME	bird	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_RENAME	bird	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt

If I change the filtering to log all NOTIFY_WRITEs, I get a flurry of activity (I de-duped all the log lines below otherwise it would be pages long)

$ sudo /Applications/FileMonitor.app/Contents/MacOS/FileMonitor -pretty |
jq --raw-output --unbuffered --arg re "$re" 'select(.file.destination|test("/dev/")?|not) | select(.event == "ES_EVENT_TYPE_NOTIFY_WRITE") | [ .event, .file.process.name, .file.destination ] | @tsv'

output:

ES_EVENT_TYPE_NOTIFY_WRITE	apsd	/Library/Application Support/ApplePushService/aps.db-wal
ES_EVENT_TYPE_NOTIFY_WRITE	bash	/Users/luke/Library/Mobile Documents/com~apple~CloudDocs/xyzzy.txt
ES_EVENT_TYPE_NOTIFY_WRITE	bird	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.bird/etilqs_bac799c714aa93e7
ES_EVENT_TYPE_NOTIFY_WRITE	bird	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.bird/etilqs_cfa75a208c505d56
ES_EVENT_TYPE_NOTIFY_WRITE	bird	/Users/luke/Library/Application Support/CloudDocs/session/db/client.db
ES_EVENT_TYPE_NOTIFY_WRITE	bird	/Users/luke/Library/Application Support/CloudDocs/session/db/server.db-wal
ES_EVENT_TYPE_NOTIFY_WRITE	cloudd	/Users/luke/Library/Caches/CloudKit/CloudKitMetadata-wal
ES_EVENT_TYPE_NOTIFY_WRITE	cloudd	/Users/luke/Library/Caches/CloudKit/com.apple.bird/495ca00354c4d66c9152fd84c120c685b6176ca8/ca7a898f7b8bf12541584d32a8d0f91029e02709/Records/Records.db-wal
ES_EVENT_TYPE_NOTIFY_WRITE	cloudd	/Users/luke/Library/Caches/CloudKit/com.apple.bird/7630364a2c49fa3d5bca30c7cabe73ffa3543026/9fadf220be21a0ed291ebfea5f836e034473cd93/MMCS/.cs/ChunkStoreDatabase-wal
ES_EVENT_TYPE_NOTIFY_WRITE	nehelper	/private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/com.apple.nehelper/TemporaryItems/NSIRD_nehelper_7N50R4/com.apple.networkextension.uuidcache.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nehelper	/private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/com.apple.nehelper/TemporaryItems/NSIRD_nehelper_Mo766E/com.apple.networkextension.uuidcache.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nehelper	/private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/com.apple.nehelper/TemporaryItems/NSIRD_nehelper_SIpEJN/com.apple.networkextension.uuidcache.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_09S10o/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_7dKm3g/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_aRjy8M/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_FbnZNA/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_kqbSoo/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_LCh16g/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_MW3AZz/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_N0NXqe/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_nwGsY9/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_oWboib/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_ox3b2R/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_pT0Uvb/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_tkdjzX/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_u8bI23/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_v3zyFJ/tasks.plist
ES_EVENT_TYPE_NOTIFY_WRITE	nsurlsessiond	/private/var/folders/h6/l1plwtys2yg1wlzspg7cd_n40000gn/T/com.apple.nsurlsessiond/TemporaryItems/NSIRD_nsurlsessiond_xE8v1x/tasks.plist

So it looks like a bunch of other helpers are involved in a simple file update on iCloud. I see nsurlsessiond, cloudd, nehelper... is there any sane way to log this type of activity?

@luckman212
Copy link
Author

leaving this crosspost here as well: Any sane way to log iCloud Drive file activity? - Ask Different

@tigersoul925
Copy link

Just a comment, all those e_types are not logged currently by filemonitor. Just some of them. Check source. Just in csse you were expecting events from permission changes etc.

@luckman212
Copy link
Author

Thanks @tigersoul925 - I'm on Ventura now so there's a built in tool called eslogger that can be used to capture these kinds of events coming through the Endpoint Security log.

@tigersoul925
Copy link

Thanks @tigersoul925 - I'm on Ventura now so there's a built in tool called eslogger that can be used to capture these kinds of events coming through the Endpoint Security log.

Oh wow I was NOT aware of eslogger and it looks great as I potentielly could get updates of permission changes etc as well now which filemonitor does not support.

How is your experience with eslogger? Does it work well? It seems in the man pages that it isn't really meant for true usage:

eslogger is not intended to be used by applications. It is not meant provide the same functionality, performance and schema stability as natively interfacing with the Endpoint Security API does. It cannot provide the integrity protection granted to System Extensions. Applications should continue to interface with EndpointSecurity(7) natively.

@luckman212
Copy link
Author

It's a great tool, has helped me a lot and works fine. I think the warning is to discourage people from lazily forking out to it from inside their apps instead of properly interfacing with the ESF API.

@tigersoul925
Copy link

It's a great tool, has helped me a lot and works fine. I think the warning is to discourage people from lazily forking out to it from inside their apps instead of properly interfacing with the ESF API.

I see. Got to try it soon. Sounds great. Just a shame it didn't appear earlier.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants