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

Jump to bottom

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 · 1 comment
Open

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

luckman212 opened this issue May 26, 2021 · 1 comment

Comments

@luckman212
Copy link

@luckman212 luckman212 commented May 26, 2021

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

@luckman212 luckman212 commented May 26, 2021

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
1 participant
@luckman212