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

[luckman212]

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]

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

[tigersoul925]

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]

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]

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]

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]

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.