Inside iCloud Drive: uploading a file

Having got Cirrus as a tool to look at what iCloud does, here’s what I have seen when copying a single 1 MB file from a local folder into the top level of my iCloud Drive. This account is based largely on what happens in High Sierra 10.13.3, although it is broadly similar to the sequences that I have seen in Sierra 10.12.6. High Sierra’s log messages are, in this case, rather clearer.

The intent to move/copy a file to iCloud Drive lands first with CloudDocs, which posts an [INFO] message for the File System Event:
[INFO] ┏300e fsevent:1/1 path:'/Users/hoakley/Library/Mobile Documents/com~apple~CloudDocs/co.eclecticlight.Cirrus.data' flags:ItemCreated|ItemInodeMetaMod|ItemIsFile|ItemCloned id:7162257441594918141 path:'/Users/hoakley/Library/Mobile Documents/com~apple~CloudDocs/co.eclecticlight.Cirrus.data' parentFileID:451060 fileID:4298998158 size:1000000 mtime:1522257049 atime:1522257049 mode:-rw-r--r-- documentID:898 generationID:1 fd:25 refs:1 appLibrary:com.apple.CloudDocs

Among the steps undertaken next is the retrieval/generation of a QuickLook thumbnail, which in this case failed, as there is no known QuickLook plugin for a file with the extension .data.

This is presumably the (very early) point at which the file appears at its destination, as CloudDocs calls for the file to be uploaded there. This is performed under the control of CloudKit, which classifies this as a ‘Modify Records Operation’ with a shortened name of Upload:
Starting operation <CKModifyRecordsOperation: 0x7fac2de9d800; operationID=CAE6ED2BDDA40DEA, qos=Utility, operationGroup={
operationGroupID = D1B7E9A397DBFB5A;
"shortened-name" = Upload;
}, >

This triggers a complex sequence of state transitions in cloudd/CloudKitDaemon, which I remarked on and illustrated before.

CloudKit then adds a child operation to the Upload to fetch a record from the PCS cache; as this is a new file, there is no such record, so CloudKit creates a new one. It then proceeds to start the upload of the asset:
Starting <CKDUploadAssetsOperation: 0x7fd5500667c0; qos=Utility, operationID=87D4E51BE1F7D829, operationGroupID=D1B7E9A397DBFB5A, operationGroupName=Upload, flags=background|allows-cellular, runningFor=0.0005819797515869141, sourceApplicationBundleID=com.apple.bird, applicationSecondaryID=4/com.apple.clouddocs.com.apple.CloudDocs:2,%>

cloudd then registers the item to be transferred with MMCS, passing it the options. In those, it checks whether the current network might have a caching server; in this case, the answer is no.

MMCS then activates and chunks the data to be transferred, and asks for a Put complete request. It then goes idle again.

CloudKit next adds a child operation to request an asset token, the URL for the user partition in iCloud. This leads through a series of exchanges to CloudKit providing MMCS with another set of options, to put the item to iCloud. Once again, MMCS chunks the data to be transferred, which is then passed up to the iCloud servers.

CloudKit then announces that it has completed the Upload Assets operation:
Finished operation <CKDUploadAssetsOperation: 0x7fd5500667c0; qos=Utility, operationID=87D4E51BE1F7D829, finishedChildOpIDs=[EB58BEE5851875C4], requestIDs=[6B0E8CE9-FDD3-4B60-B28D-64178C19BFBC], operationGroupID=D1B7E9A397DBFB5A, operationGroupName=Upload, stateFlags=executing, flags=background|allows-cellular, state=Complete, runningFor=0.6047440767288208, MMCSMetrics=<CKDOperationMetrics: 0x7fd55048daf0; startDate=2018-03-28 17:10:51 +0000, duration=0.000, queueing=0.000, executing=0.000, bytesUploaded=0, bytesDownloaded=0, connections=0, connectionsCreated=0, requests=0>, sourceApplicationBundleID=com.apple.bird, applicationSecondaryID=4/com.apple.clouddocs.com.apple.CloudDocs:2,%>
and that it has completed the operation to modify records:
Finished operation <CKDModifyRecordsOperation: 0x7fd55040ba80; qos=Utility, operationID=CAE6ED2BDDA40DEA, finishedChildOpIDs=[BE71CBAFB4A35CE2, 87D4E51BE1F7D829], requestIDs=[6B0E8CE9-FDD3-4B60-B28D-64178C19BFBC], operationGroupID=D1B7E9A397DBFB5A, operationGroupName=Upload, stateFlags=executing, flags=background|allows-cellular, state=Complete, runningFor=0.6184440851211548, MMCSMetrics=<CKDOperationMetrics: 0x7fd55048daf0; startDate=2018-03-28 17:10:51 +0000, duration=0.000, queueing=0.000, executing=0.000, bytesUploaded=0, bytesDownloaded=0, connections=0, connectionsCreated=0, requests=0>, sourceApplicationBundleID=com.apple.bird, applicationSecondaryID=4/com.apple.clouddocs.com.apple.CloudDocs:2,%>
and that completes the whole upload.

CloudDocs finally publishes a notice announcing the completion of the upload:
[NOTICE] finished uploading 1 items (1.0 MB) in com.apple.CloudDocs

This appears in little more than a second after the start of the whole sequence, at which stage the Finder’s iCloud sync progress indicator is still incomplete. In this case, there were two further series of exchanges involving cloudd, CloudKit, and CloudDocs. The first performed a ‘sync up’ to modify records, and involved cloudd and CloudKit.

The second was triggered by an incoming message from APS, Apple’s Push Service, which was initially handled by CloudDocs. This triggered a CloudKit operation to fetch record zone changes, or a ‘Sync down (push triggered)’. My interpretation of that is that the iCloud service pushed my Mac a request for it to synchronise with iCloud Drive, which was to propagate the change that had just been made in its contents, by my Mac!

Eventually, CloudDocs reported:
[NOTICE] received 2 edited items from the cloud for com.apple.CloudDocs

It then applied the changes, which reflected the upload of my test file to iCloud Drive:
[INFO] ┏3250 Apply Changes[1:2669]: attempting to apply update
server item: i:com.apple.CloudDocs:C8B0A06D-6F4F-4EF3-84E9-84BF56E0FDB8 rk:2669 pcs:u st{p:root[1] n:"co.eclecticlight.Cirrus.data" doc etag:f02 bt:1522257049 m:rw-} ct{etag:f01 mt:1522257049 sz:1.0 MB (1000000) n:"co.eclecticlight.Cirrus.data" sig:010e78c62cca2c81bb0a765659bbb2991f0676f172 device:2}
local item: r:1116 i:com.apple.CloudDocs:C8B0A06D-6F4F-4EF3-84E9-84BF56E0FDB8 al:1 up:idle uv:1 st{p:root[1] n:"co.eclecticlight.Cirrus.data" doc etag:f02 bt:1522257049 m:rw- doc:898 ino:4298998158 gen:1 sc:docs} ct{etag:f01 mt:1522257049 sz:1.0 MB (1000000) n:"co.eclecticlight.Cirrus.data" sig:010e78c62cca2c81bb0a765659bbb2991f0676f172 device:2} thumb{greedy}

This was about 3.5 seconds after the start of this series of processes, and roughly coincided with the moment that the progress icon was removed from the Finder window. The upload was complete.

I have summarised the main blocks of exchanges, using the same colour code as in Cirrus, in the following diagram, which gives you an idea of how complex it is to execute a single action. Look through the log entries in Cirrus, and you should be able to trace the processes.

iCloudOps1

These should give you an idea of the sequence of events which you should see during a normal and successful upload of a test file to iCloud Drive. They exclude all the network transfer work, which is performed by com.apple.mDNSResponder, com.apple.network, nsurlsessiond, and the like. Those subsystems are not covered in Cirrus: if you suspect that the problems lie there, open the same time period using Consolation 3, and you can trudge through that detail.

I have also not considered the role of com.apple.duetactivityscheduler (DAS), the dispatching system which seems to schedule the transfer of data. If you are still running Sierra, you should bear in mind that Macs which are left running Sierra continuously for periods over five days can suffer failure of the DAS subsystem; that could explain failure to transfer files to iCloud. A simple indicator of that problem is the resulting failure in timed automatic Time Machine backups, another feature dispatched by DAS.

You can examine DAS in detail using Consolation 3, or DispatchView (from Downloads above).