It’s not uncommon to experience delays and even failures when your Mac syncs with iCloud. Tracking what’s going wrong with syncing databases like Contacts and Calendar is extremely complex, so Cirrus offers a standard test based not on a database sync but on transferring one 1 MB file to iCloud Drive. Sometimes merely running this test can prove sufficient to kickstart iCloud syncing, but its primary purpose is to review what happens in the log during that process.

The first time that you attempt this, you’ll find it best performed when everything else on your Mac is quiet, perhaps first thing in the morning before you’ve started any apps, and certainly before opening apps which use iCloud. Running the test is simple: as your system clock reaches 00 seconds, press Command-1 in Cirrus, or release the Test Upload command in the Window menu. Watch what happens with the iCloud sync circle in a Finder window, and note the number of seconds when that icon fills and is removed.

Then use the Open Log Window command in the Window menu, set the Start time to just before you initiated the test upload, and the End time to at least the time that iCloud sync completed, and no less than ten seconds later (in High Sierra and earlier, 20 seconds). Finally click on the Get log button, and you’re ready to study what happened. To clean up the test files, use the Clean Up Test command in the Window menu.

You may also find it useful to obtain a full log excerpt for the same period using Ulbow or Consolation. In Ulbow, set the reference time to that of the end of the period, and the Period to the negative of the period between the start and end, such as -10 seconds.

Cirrus performs the test as follows:

1. It first writes a 1 MB file containing 0x88 bytes as data to ~/Library/Preferences/co.eclecticlight.Cirrus.data
2. It then creates a URL to a new file co.eclecticlight.Cirrus.data in your iCloud Drive, at the path ~/Library/Mobile Documents/com~apple~CloudDocs/co.eclecticlight.Cirrus.data
3. If that succeeds, it removes that new file and copies the 1 MB file from ~/Library/Preferences/co.eclecticlight.Cirrus.data into your iCloud Drive at ~/Library/Mobile Documents/com~apple~CloudDocs/co.eclecticlight.Cirrus.data
4. If any step in that fails, Cirrus reports that it was unable to transfer the test file in an alert.

The Clean Up Test command simply deletes the two files ~/Library/Preferences/co.eclecticlight.Cirrus.data and ~/Library/Mobile Documents/com~apple~CloudDocs/co.eclecticlight.Cirrus.data.

The total length of the log obtained by Cirrus is likely to be more than around 800 lines, so it’s easy to panic or get lost in its entries. However, if you look at its broad structure, you’ll see three distinct phases:

1. the upload phase, in which CloudKit (blue) and cloudd (grey) work with MMCS (green) to upload the new item;
2. the sync up phase, in which the new file is created in iCloud Drive;
3. the sync down phase, in which the file details are sent back to your Mac and generate a stub file in your local iCloud Drive folder.

Each phase is clearly marked by red log entries from CloudDocs which describe what is happening at that stage, typically with a [NOTICE] announcement in the log. Scrolling through the log excerpt, these should be easy to identify, and reveal the overall sequence of events.

Each phase starts with a series of entries by CloudKit (blue) and cloudd (grey) which explain what is happening in great detail. cloudd actually performs much of the work during these, and during the upload phase you should see two separate sessions in which MMCS actually does the copying. These are summarised in the diagram below, and detailed in the log entries shown in the Appendix.

Here’s a tear-out PDF version for you to keep: iCloudTestUpload1

Knowing what a normal sync test should look like enables you to spot errors and failures when things don’t go right. Surprisingly, there is very little involvement of Catalina’s pervasive privacy system TCC. However, if an error occurs in that, it’s likely to propagate into a refusal in a kernel entry, now seen in grey.

Appendix: Log entries from Cirrus

Taken from Cirrus in Catalina 10.15.2. Times are given in decimal seconds throughout.

The menu command to start the test:
00.852 Cirrus AppKit perform action for menu item (not shown in Cirrus, but seen in Ulbow)

Initial steps, leading to the announcement of the start of the upload phase:
01.365 CloudDocs [WARNING] could not find container for id: <private>
01.365 CloudDocs [WARNING] could not find container for id: <private>
01.865 CloudDocs [INFO] ┏15eb4 fsevent:1/2 path:'<private>' flags:<private> id:7162257444087043630 <private>
01.865 [bird] fsevent
01.868 [bird] coord-read
01.868 [bird] Read (Async) options: 10001 -- URL: <private> -- purposeID: FAFF9EFE-69FB-4CC9-9FDB-DEB47E17A8D1 -- claimID: DCB7FF54-EC9A-4A6B-9D62-1B91198916DC
01.868 CloudDocs [INFO] ┗15eb4
01.868 CloudDocs [INFO] ┏15ec2 fsevent:2/2 path:'<private>' flags:<private> id:7162257444087043637 <private>
01.868 [bird] fsevent
01.868 [bird] Claim DCB7FF54-EC9A-4A6B-9D62-1B91198916DC granted in client
01.868 [bird] Claim DCB7FF54-EC9A-4A6B-9D62-1B91198916DC invoked in client
01.869 CloudDocs [INFO] ┗15ec2
01.871 [bird] !quicklook/thumbnail-retrieval
01.873 CloudDocs [NOTICE] uploading 1 documents in <private>
01.873 [bird] upload

then there’s a sequence of blue CloudKit entries referring to the Operation with a shortened name of Upload

01.875 CloudKit Giving <private> blanket access to any container
01.875 [cloudd] daemon/modify-records
01.875 [cloudd] [Operation 0x7fe6e915ea20] Starting operation
and CloudKit announces it is starting the operation

clouddd (grey) transitions from state 1, through a sequence 1, 2, 3, 4, 5, 6, 7, 9, 8

CloudKit then adds a child operation

cloudd transitions from state 1, 2, 2

01.875 CloudKit Didn't get PCS data for record <private>: no PCS data and no error. Fetching the zone PCS and creating new PCS data
01.875 CloudKit Finished operation <CKDPCSCacheRecordFetchOperation: 0x7fe6e5d60b00; qos=Utility, operationID=73759FD822B8E249, operationGroupID=BC577671049CC96C, operationGroupName=Upload, stateFlags=executing, flags=background|allows-cellular, state=Complete, runningFor=0.0003420114517211914, <private>>
01.875 CloudKit Creating new PCS object for record <private>
01.876 CloudDocs [WARNING] could not find container for id: <private>
01.877 CloudDocs [WARNING] could not find container for id: <private>

cloudd transitions from state 8, 10, 11

CloudKit adds another child operation

cloudd now in state 12

CloudKit starts the child operation
cloudd transitions to state 2

MMCS then takes over the transfer of the data, once its options have been set up
01.883 [cloudd] mmcs-register-items
01.883 MMCS RequestOptions kMMCSRequestOptionContainerIdentifier:com.apple.clouddocs
01.883 MMCS RequestOptions kMMCSRequestOptionReturnPreauthorizationRequestObject:1
01.883 MMCS RequestOptions/kMMCSRequestOptionItemOptions:0 kMMCSRegisterFileOptionChunk:1
01.883 MMCS RequestOptions/kMMCSRequestOptionItemOptions:0 kMMCSItemID:2
01.883 MMCS RequestOptions/kMMCSRequestOptionItemOptions:0/kMMCSWrappingState kMMCSReferenceSignature:{length = 21, bytes = 0x016d422b8fa3b245ed96859cc077e9600822905e26}
01.883 MMCS RequestOptions/kMMCSRequestOptionItemOptions:0/kMMCSWrappingState kMMCSReferenceObject:Key<16 bytes with hash lV1oznZq>

01.884 MMCS Engine 0x7fe6e7052fe0 is adding request <register req0015 0x7fe6e719c010 pri0(default)>
01.884 MMCS Engine Status: was idle, going active
01.892 MMCS Chunking finished for itemId 2 of 1000000 bytes in 0.0075 sec.
01.892 MMCS Engine 0x7fe6e7052fe0 completed request <register req0015 0x7fe6e719c010 pri0(default)> ([2 chunk ==> 010e78c62cca2c81bb0a765659bbb2991f0676f172 1000000 bytes 31 chunks])
01.892 MMCS Asking for Inline Put Complete Request Version 2
01.892 MMCS Engine 0x7fe6e7052fe0 request will notify request <register req0015 0x7fe6e719c010 pri0(default)> done
01.893 MMCS Engine Status: was active, going idle
01.893 MMCS Engine 0x7fe6e7052fe0 is removing request <register req0015 0x7fe6e719c010 pri0(default)>

Then there’s another series of cloudd and CloudKit exchanges
around 01.950, BoringSSL activity is seen in Ulbow for the data transfer session

02.234 CloudKit Using MMCS options: <private>
02.234 [cloudd] mmcs-put-items
and mmcs request options are set again

MMCS is active again with
02.234 MMCS itemId:2 sig:010e78c62cca2c81bb0a765659bbb2991f0676f172 ref:016d422b8fa3b245ed96859cc077e9600822905e26
02.234 MMCS Engine 0x7fe6e7052fe0 is adding request <put req0016 0x7fe6e7056b20 pri0 Bg>
02.234 MMCS Engine Status: was idle, going active
02.234 MMCS Chunking item (2) 1 of 1
02.234 MMCS Chunking started for itemId 2 with signature 010e78c62cca2c81bb0a765659bbb2991f0676f172
02.235 MMCS Chunking finished for itemId 2 of 1000000 bytes in 0.0001 sec.
02.235 MMCS Server Receipt Received. itemId:2 receipt:CAogTCNgpRxil/zSCdVGodkSQ0kEapjOLVJ6ANZOq+TFafgSLxDCnujn+y0YwqjbhvwtIgEAMKOe6Of7LTjCnujn+y1SBAZ28XJaBCKQXiZgwIQ9 expiry:01/20/2020, 02:45:02.1460 sig:010e78c62cca2c81bb0a765659bbb2991f0676f172 ref:016d422b8fa3b245ed96859cc077e9600822905e26 len:1000000
02.235 MMCS Engine 0x7fe6e7052fe0 request will notify request <put req0016 0x7fe6e7056b20 pri0 Bg> done
02.235 MMCS Engine>Status: was active, going idle
02.235 MMCS Engine 0x7fe6e7052fe0 is removing request <put req0016 0x7fe6e7056b20 pri0 Bg>

The end of the upload phase is marked by CloudDocs (red):
02.238 CloudDocs [NOTICE] finished uploading 1 items (<private>) in <private>

02.030 a period of icon animation is seen in Ulbow’s version of the log, which probably corresponds to the icon display in the Finder.

The sync up phase is announcedL
02.240 CloudDocs [NOTICE] sending 1 items to the cloud for <private>
02.244 CloudKit Setting zoneishKeyID on record <private> to (null)
02.244 [bird] sync-up
02.244 [bird] client/modify-records

This is concluded by
02.794 CloudKit Record <private> was successfully saved to the server

Finally the start of the sync down phase:
02.798 CloudDocs [INFO] ┏15fda <private>: starting sync down
02.798 CloudDocs [INFO] ┗15fda
02.798 [bird] sync-down
02.798 CloudDocs [INFO] ┣15fe4 starting fetch record changes operation for <private> from token <private>
02.798 [bird] fetch-record-subresources
02.798 [bird] client/fetch-record-changes

This concludes with
03.013 CloudDocs [INFO] ┳15fe4 got a record in operation <private>
03.013 CloudDocs [INFO] ┗15fe4
03.014 CloudKit Record <private> was decrypted
03.014 CloudDocs [INFO] ┳15fe4 got a record in operation <private>
03.014 CloudDocs [INFO] ┗15fe4
03.016 CloudKit Record <private> was decrypted
03.016 CloudKit All record callbacks are complete. Finishing fetch operation
03.016 CloudKit All record callbacks are complete. Finishing decrypt operation if any.
03.016 CloudDocs [INFO] ┳15fe4 got a record in operation <private>
03.016 CloudDocs [INFO] ┗15fe4
03.016 [bird] server-zone/did-sync-down
03.016 CloudDocs [NOTICE] received 2 edited items from the cloud for <private>

The transfer is finally complete.