A lot of Mac users are suffering problems with iCloud – some with syncing data such as Calendars, and many with getting files loaded into iCloud Drive and accessible from there. As we are supposed to treat anything iCloud as a Black Box which just works, when it doesn’t it’s very hard to know what to do. About the only suggestion in most cases is to disconnect and reconnect, which is usually as purposeful as clutching a good luck charm.
I’m starting to try to understand how iCloud works, starting with iCloud Drive, in Sierra and High Sierra. There seems to be almost no existing information about this – even Apple’s developer documentation is scant and vague. If you know any better, please join in with comments.
My starting point is what should be one of the simplest actions: copying a single file from local storage to a folder in iCloud Drive. My first lesson is that the unified log is a rich source of information, but it only becomes meaningful when the log’s privacy protection is turned off. Trying to make sense of the log when the normal privacy setting is in force is futile, as all the useful information is censored by <private>.
I initiated the copy in the Finder, Opt-dragging the file over from one Finder window to another, so the relevant section of log starts with a barrage of log entries from com.apple.CFPasteboard showing that action being handled. This then becomes a filecoordination claim, with a log entry of the form
com.apple.foundation.filecoordination claims Finder Foundation Write options: 0 -- URL: file:///Users/hoakley/Library/Mobile%20Documents/com~apple~CloudDocs/backup1/SierraCopyToiCloud.text -- purposeID: com.apple.desktopservices.copyengine
or
com.apple.foundation.filecoordination claims DesktopServicesHelper Foundation Read options: 1 -- URL: file:///Users/hoakley/Documents/0newDownloads/SierraCopyToiCloud.text -- purposeID: com.apple.desktopservices.copyengine
which then initiates the copy.
The main actors involved in handling the iCloud operations are:
- com.apple.clouddocs
- com.apple.cloudkit
- com.apple.mmcs
- com.apple.duetactivityscheduler
and several supporting services, including cloudd. I look at these in turn before putting the whole process together. Although there are undoubtedly some differences between Sierra 10.12.6 and High Sierra 10.13.3, log entries are broadly very similar, and there don’t appear to be substantial differences in the actors or sequences involved. That surprised me.
I performed these tests in the UK (southern England), and my iCloud Drive storage was located as Amazon’s AWS servers for western Europe, apparently in Ireland.
com.apple.clouddocs
The main role of the CloudDocs subsystem appears to be to get attribute values for items in iCloud, and act as the information broker between iCloud and macOS (or iOS). Its log entries have the distinctive use of ┏ (U_250F) and ┗ (U+2517) to mark out matching iCloud calls, with their hex serial numbers, in exchanges like
com.apple.clouddocs [INFO] ┏1b6e Consolation3[10745] (default) -[BRCXPCRegularIPCsClient getAttributeValues:forItemAtURL:reply:] /Users/hoakley/Library/Mobile Documents/com~apple~CloudDocs/backup1
com.apple.clouddocs [INFO] ┏1b70 com.apple.finder[380] (default) -[BRCXPCRegularIPCsClient getAttributeValues:forItemAtURL:reply:] /Users/hoakley/Library/Mobile Documents/com~apple~CloudDocs/backup1
com.apple.clouddocs [INFO] ┗1b6e
com.apple.clouddocs [INFO] ┗1b70
You will also come across a link entry sometimes:
com.apple.clouddocs [INFO] ┣44 starting fetch record changes operation for com.apple.CloudDocs from token <…>
CloudDocs makes copious entries handling queries, in groups such as
com.apple.clouddocs [INFO] ┏1b9e com.apple.finder[380] (default) -[BRCXPCRegularIPCsClient getAttributeValues:forItemAtURL:reply:] /Users/hoakley/Library/Mobile Documents/com~apple~CloudDocs/backup1/201612-306geniusTips.txt
com.apple.clouddocs [INFO] ┗1b9e
com.apple.clouddocs [INFO] com.apple.finder[380]: reply({
NSURLUbiquitousItemDownloadingStatusKey = NSURLUbiquitousItemDownloadingStatusCurrent;
NSURLUbiquitousItemIsDownloadingKey = 0;
NSURLUbiquitousItemIsUploadedKey = 1;
NSURLUbiquitousItemIsUploadingKey = 0;
"_NSURLUbiquitousItemDownloadRequestedKey" = 1;
}, (null))
com.apple.cloudkit
CloudKit is exposed to developers, where it provides interfaces for moving data between apps and iCloud containers. In this situation, it performs the transactions needed to carry out the file copy, including invoking MMCS. Although its steps appear similar in Sierra and High Sierra, its log entries are much clearer in High Sierra, and examples are shown below.
com.apple.mmcs
MMCS is a service which appears to act as a transfer engine, being driven by CloudKit to perform the data transfers required. A typical log sequence might start
com.apple.mmcs default Engine Status: was idle, going active
com.apple.mmcs default Chunking item (3777) 1 of 2
com.apple.mmcs default Chunking started for itemId 3777 with signature …
com.apple.mmcs default Chunking finished for itemId 3777 of 491 bytes in 0.0001 sec.
com.apple.mmcs default Chunking item (3778) 2 of 2
com.apple.mmcs default Chunking started for itemId 3778 with signature …
com.apple.mmcs default Chunking finished for itemId 3778 of 43 bytes in 0.0000 sec.
com.apple.mmcs default Server Receipt Received. itemId:…
and continue with further transfer actions.
com.apple.duetactivityscheduler
I was surprised to see the involvement of the macOS Duet Activity Scheduler (DAS) in these actions, in both Sierra and High Sierra. DAS is part of the activity scheduling and dispatching systems within macOS and iOS, but undocumented. In Sierra systems which are left running for long periods (typically over 5 days), it suffers a bug which causes it to collapse eventually, leading to a failure to perform automatic hourly Time Machine backups, for example.
DAS is here not paired with CTS (part of XPC) which normally performs the actions which it dispatches, which also appears strange. Instead, it seems to work directly with iCloud subsystems:
nsurlsessiond com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1> submitted to pool com.apple.cloudkit.BackgroundConnectionPool
com.apple.duetactivityscheduler client nsurlsessiond DuetActivityScheduler SUBMITTING: com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>
nsurlsessiond CFNetwork TIC [0x7f92f79454f0]: DAS scheduler submitted activity 0x7f92f5657b30
com.apple.duetactivityscheduler default DuetHeuristic-BM DuetActivitySchedulerDaemon Submitted Activity: <_DASActivity: "com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>", UserInitiated, 300s, [3/25/18, 9:21:11 AM - 3/25/18, 9:21:21 AM], Group: "com.apple.cloudkit.BackgroundConnectionPool", Networking: Upload=0, Size=5000, WiFi-Only=0, Dark-Wake Eligible, Related Apps: ( "com.apple.bird" ), User Specified: { }>
com.apple.duetactivityscheduler default DuetHeuristic-BM DuetActivitySchedulerDaemon Start network path monitoring for 'com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>'
com.apple.duetactivityscheduler scoring DuetHeuristic-BM DuetActivitySchedulerDaemon com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>:[
] sumScores:30.477778, denominator:34.700000, FinalDecision: Can Proceed FinalScore: 0.878322}
com.apple.duetactivityscheduler scoring DuetHeuristic-BM DuetActivitySchedulerDaemon 'com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>' DecisionToRun:1 (Bypasses Predictions)
com.apple.duetactivityscheduler lifecycle(activityGroup) DuetHeuristic-BM DuetActivitySchedulerDaemon With com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1> ...Tasks running in group com.apple.cloudkit.BackgroundConnectionPool are 3!
com.apple.duetactivityscheduler default DuetHeuristic-BM DuetActivitySchedulerDaemon Stop network path monitoring for 'com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>'
com.apple.duetactivityscheduler lifecycle DuetHeuristic-BM DuetActivitySchedulerDaemon Running activities : (
"com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>"
)
com.apple.duetactivityscheduler client nsurlsessiond DuetActivityScheduler STARTING: com.apple.CFNetwork-cc-400-552-Task <com.apple.cloudd>.<>.<1>
I suspect that DAS may be responsible for dispatching updating, and perhaps the transfer of bulk file data, between iCloud and macOS (and iOS).
cloudd
Another characteristic pattern seen in the log is the series of state transitions for cloudd/CloudKitDaemon. These occur in sequences, such as
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Starting operation
com.apple.cloudkit LogFacilityOP cloudd CloudKitDaemon Starting <CKDModifyRecordsOperation: …>
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 1 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 2
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 2 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 3
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 3 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 4
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 4 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 5
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 5 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 6
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 6 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 8
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation transitioning from state 8 (cancelled=0, stop=0, error=0)
cloudd CloudKitDaemon [Operation 0x7ffef0da7160] Operation is now in state 7
I have no idea what is happening here.
Putting it all together
The sequence of iCloud-derived log entries which occur when copying a file to iCloud Drive characteristically starts with a notice from com.apple.clouddocs, following which CloudKit starts an upload operation:
com.apple.clouddocs [NOTICE] uploading 1 documents in com.apple.CloudDocs
com.apple.cloudkit Starting operation <CKModifyRecordsOperation: 0x7fea5a7d88b0; operationID=F79247484F68DE18, qos=Utility, operationGroup={
operationGroupID = A8F5425E1D53FD3C;
"shortened-name" = Upload;
}, >
You will then see some of the sequences shown above, which progress the operation through until completion. That is marked by a sequence from CloudKit and CloudDocs:
com.apple.cloudkit Finished operation <CKModifyRecordsOperation: 0x7fea5a7d88b0; operationGroup={
operationGroupID = A8F5425E1D53FD3C;
"shortened-name" = Upload;
}, operationID=F79247484F68DE18, qos=Utility, stateFlags=executing, metrics=<CKOperationMetrics: 0x7fea5a7cd310; cloudKitMetrics=<CKMetric: 0x7fea5a7d7720; startDate=2018-03-25 13:07:05 +0000, duration=3.472, queueing=0.000, executing=6.930, bytesUploaded=913, bytesDownloaded=2864, connections=1, connectionsCreated=1>, MMCSMetrics=<CKMetric: 0x7fea5a75f700; startDate=2018-03-25 13:07:08 +0000, duration=0.000, queueing=0.000, executing=0.585, bytesUploaded=1836, bytesDownloaded=75, connections=2, connectionsCreated=2>>>
com.apple.clouddocs [NOTICE] finished uploading 1 items (534 bytes) in com.apple.CloudDocs
I hope that helps you follow what is going on in your log when you are experiencing problems with iCloud. I am now looking at how best to build this into a tool to help diagnose those problems.
The Eclectic Light Company 