This page is designed to give anyone working on the ActiveSync library in Horde 5.x a general overview of logic flow and what happens where and when.
The logic for handling ActiveSync requests is split between 3 different libraries currently - Horde_Rpc, Horde_Core, and obviously Horde_ActiveSync. Horde_Rpc only handles the initial request and basically just passes on control to Horde_ActiveSync so this page will focus only on the other two libraries.
This library contains the main logic for decoding WBXML from EAS requests, passing the request to the appropriate controller and then sending properly encoded responses back to the client.
The following is a general overview of the important classes in this library and what they are responsible for:
Core contains any code specific to handling Horde Groupware collections. This is where requests for information and changes to information are actually handled.
There are also the individual documents for each collection type, such as MS-ASEMAIL, MS-ASTASKS etc... These documents are the best place to start when trying to track down issues such as "Protocol Error" issues with certain clients.
The basic bit to know about the EAS protocol is that it is encoded using WBXML. That is, binary encoded XML data. Again, the structure/schema of WBXML data is beyond the scope of this page. Instead of decoding the entire request first and then handling it, Horde_ActiveSync decodes the data and handles it on the fly. That is, we decode each individual message/object as it comes in and handle it in-line, so to speak. This is to avoid keeping more in memory than is necessary. The same is true for encoding - we don't wait to enocde the entire response - we encode and send the response to the output stream as soon as we can. The actual encoding/decoding is done in the Horde_ActiveSync_Wbxml_* classes. The codepages/schema is defined in //Horde_ActiveSync_Wbxml::.
I have a long-standing item on my todo list to generate an activity diagram for the program flow of an EAS request, but in the meantime here is a description of what happens.
EAS requests hit rpc.php first. There are a number of ways that these are differentiated from other RPC requests, but the main give-away is the REQUEST_URI containing Microsoft-Server-ActiveSync. A few things happen here before continuing. First, EAS requests are session-less, meaning that the entire Horde environment needs to be setup for each request. This is handled by explicitly setting $session_control = 'None' to force the use of the Null session driver in Horde. From there, we perform the same logic and checks like every other Horde RPC request. This includes having to initialize the Horde environment with NO authentication.
From here, we instantiate a Horde_Rpc_ActiveSync object and inject a Horde_ActiveSync object (which is created using Horde_Core_Factory_ActiveSyncServer).
Here, we perform some sanity checking on the request and sniff out what type of request we are handling. OPTIONS and Autodiscover requests are handled a little differently, but for now we will concentrate on the "normal" request handling.
The client must send certain data, apart from the WBXML structure, with each request. This data is either present as "normal" GET variables or is sent as BASE64 encoded binary data sent in QUERY_STRING (see Horde_ActiveSync::getGetVars()). The format of this binary data is beyond the scope of this page, but the data is decoded in Horde_ActiveSync_Utils::decodeBase64().
Flow is turned over to Horde_ActiveSync::handleRequest(). This is where the interesting stuff starts to happen.
First, we perform some checks, normalization, and call the versionCallback hook if it's present. If all is well, we finally attempt authentication. Authentication to Horde is a massive topic and it's only complicated more by layering ActiveSync on top of it. I will try to give a brief overview here. For a more detailed description of the general Horde authentication layer, see Jan's excellent series of posts on his blog.
Thanks to broken clients, different supported authentication mechanisms and other idiosyncrasies, we need to perform some magic to make sure we have the user's credentials. For this, there is Horde_ActiveSync_Credentials. This class, when constructed and injected with the Horde_ActiveSync object, will have two properties set: username and password. For the purposes of this page, we will assume a typical setup where the client properly sends credentials using HTTP BASIC and we are NOT using X509 certificates.
Once we have found the credentials, we call Horde_ActiveSync::authenticate(). This performs a few checks then ultimately passes control to Horde_Core_ActiveSync_Driver::authenticate(). Since some broken clients always send the email address as the username, plus the fact the Autodiscover requests ALWAYS use the email address, we need to normalize the username to the correct form. This is handled in Horde_Core_ActiveSync_Driver::getUsernameFromEmail() and is partially affected by the $GLOBALS['conf']['activesync']['autodiscovery'] setting (yes, this name is misleading since it is now used for more than just autodiscovery).
Once in Horde_Core_ActiveSync_Driver::authenticate() we use the Horde_Core_ActiveSync_Auth object that was injected when the driver was created to perform the actual authentication. The reason for this authentication wrapper is to allow for combinations of a "normal" Horde auth driver along with a transparent driver like X509 to support clients that allow for certificates along WITH credentials. For this page, we will assume a "normal" authentication - and as such, the actual authentication task is delegated to the 'base_driver' in Horde_Core_ActiveSync_Auth. That is, the authentication driver that is returned by
$injector->getInstance('Horde_Core_Factory_Auth')->create()
Once we have gotten authentication out the way, we perform some checks on the device/client. This includes things like making sure the device entry exists in our storage backend (or gets created if it doesn't), checking to see if the maximum protocol version we can handle has changed - and if so, notifying the client. We also call some hooks and callbacks to allow checking various permissions etc... All of this is handled in Horde_ActiveSync::_handleDevice(). At the end of that call (if successful), we know we have a device object available and the client is allowed to connect. Any failure here will result in an Exception being thrown and subsequently an appropriate HTTP error code to be sent back to the client.
Now we take care of setting the provisioning flag and read the WBXML header in from the input stream. Provisioning support allows the server to take control of certain security settings on the client and also enables the ability to remote-wipe the client from the server. The provisioning flag is from Horde's permissions system and indicates the level of security required:
Next we check to see if the client accepts Multipart responses. This is typically used when fetching large amounts of data like e.g, an email attachment. This is indicated by the presence of a specific header or GET variable. We will assume this is not the case for this page.
Now we can take care of the actual command the client is attempting to perform. These are handled by Horde_ActiveSync_Request_* objects. Again, the name of these objects are a bit outdated and are planned to be renamed in H6. The object is instantiated and the handle() request is called. If all goes well, a value of true is returned and control is returned back to the RPC layer to finish up.
The Horde_ActiveSync_Request_* objects are responsible for enforcing the schema of whatever request is being handled, passing off any incoming additions/deletions/changes to the backend and delegating the responsibility for storing any data that needs to be persisted. This includes the collection state and the sync cache. This are explained in the section on the client life cycle.
I should be noted here that ActiveSync clients are able to issue requests while other requests are still running. I.e., if the user changes an entry, a new SYNC request can be issued, even though there is currently a PING request running. After the SYNC request is handled, the client can then issue another PING reqeust etc... The sync cache is used to track this and detect these concurrent requests and kill off the most appropriate request.
There are almost 2 dozen different types of requests that handle things from synchronizing the folder structure to validating S/MIME certificates. The more common request objects are:
This is where the bulk of the action is performed and this description is of course a gross over-simplification. There are many other objects that are involved in handling the request - the responsibility of each of these objects are outlined in the General Library Structure section.
What we will describe is the life cycle of a client-server pairing from the initial connection to be able to synchronize changes. Let's start with a fresh, never before connected client. The details and order of things vary from EAS version to version. This is designed as a general overview and most closely resembles what happens in EAS version >= 14.
The first thing that happens is the OPTIONS request. This essentially tells the server what protocol versions the client supports and the server responds with (among other things) the version that it will be using. This is usually where the device object is first created. TODO: Flesh this out with more details.
Second will normally be a SETTINGS request. This is where the client can give the server details about the device and/or OS, application name etc... Normally this is responded to with server details about the user account. The following is an example synclog of the SETTINGS request and response using a Windows 10 Mail client:
2016-11-14T17:03:59+00:00 INFO: [10030] Horde_Core_ActiveSync_Driver::authenticate() attempt for mike 2016-11-14T17:03:59+00:00 INFO: [10030] SETTINGS request received for user mike 2016-11-14T17:03:59+00:00 INFO: [10030] Device entry exists for 340B5431BBC4241BB73F622B4C6D18E9, updating userAgent, version, and supported. 2016-11-14T17:03:59+00:00 INFO: [10030] GET VARIABLES: Array ( [ProtVer] => 14.1 [Cmd] => Settings [Locale] => 1033 [DeviceId] => 340b5431bbc4241bb73f622b4c6d18e9 [PolicyKey] => 0 [DeviceType] => WindowsMail ) 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:Settings> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:DeviceInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:Set> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:Model> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I VMware Virtual Platform 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:Model> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:IMEI /> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:FriendlyName> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I DESKTOP-E96J0OF 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:FriendlyName> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:OS> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I Windows 10.0.14393 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:OS> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:OSLanguage> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I English 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:OSLanguage> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:PhoneNumber /> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:UserAgent> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I MSFT-WIN-3/10.0.14393 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:UserAgent> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:EnableOutboundSMS> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:MobileOperator> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I OperatorName 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:MobileOperator> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:Set> 2016-11-14T17:03:59+00:00 INFO: [10030] Device entry exists for 340B5431BBC4241BB73F622B4C6D18E9, updating userAgent, version, and supported. 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:DeviceInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:UserInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I <Settings:Get /> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:UserInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] I </Settings:Settings> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Settings> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Status> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O 1 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Status> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:DeviceInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Status> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O 1 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Status> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:DeviceInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:UserInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Status> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O 1 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Status> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Get> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Accounts> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:Account> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:AccountName> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O Default Identity 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:AccountName> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:EmailAddresses> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:PrimarySmtpAddress> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O mike@theupstairsroom.com 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:PrimarySmtpAddress> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O <Settings:SmtpAddress> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O mike@theupstairsroom.com 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:SmtpAddress> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:EmailAddresses> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Account> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Accounts> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Get> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:UserInformation> 2016-11-14T17:03:59+00:00 DEBUG: [10030] O </Settings:Settings>
For the purposes of this page, we are going to ignore the PROVISIONING stuff. The next step is the FOLDERSYNC request:
2016-11-14T17:03:59+00:00 DEBUG: [10029] I <FolderHierarchy:FolderSync> 2016-11-14T17:03:59+00:00 DEBUG: [10029] I <FolderHierarchy:SyncKey> 2016-11-14T17:03:59+00:00 DEBUG: [10029] I 0 2016-11-14T17:03:59+00:00 DEBUG: [10029] I </FolderHierarchy:SyncKey> 2016-11-14T17:03:59+00:00 DEBUG: [10029] I </FolderHierarchy:FolderSync>
First, the client requests a SyncKey of 0. This indicates it is a fresh start and that the server should discard any previous sets of state it may have for this client and user. The server fetches the list of folders that are available. For this purpose each groupware share (address book, calendar etc...) is considered a folder. The entry point for this is Horde_Core_ActiveSync_Driver::getFolderList().
At this point we should talk about the backend's id and the ActiveSync UID for each folder. From the client's point of view, all it cares about is the uid for the folder. We create new UIDs whenever a new folder is encountered. The mapping of UIDs to backend ids is managed by the Horde_ActiveSync_State driver. So, you will see something like this in the sync log:
2016-11-14T17:03:59+00:00 INFO: [10029] Horde_Core_ActiveSync_Driver::getFolderList() 2016-11-14T17:03:59+00:00 INFO: [10029] Device entry exists for 340B5431BBC4241BB73F622B4C6D18E9, updating userAgent, version, and supported. 2016-11-14T12:04:00-05:00 INFO: [10029] Creating new folder uuid for Calendar:1w_UP1B0Fbgun61fg3dAqLJ: A2603e3ee 2016-11-14T12:04:00-05:00 INFO: [10029] Creating new folder uuid for @Contacts@: Cd1b7031f 2016-11-14T12:04:00-05:00 INFO: [10029] Creating new folder uuid for @Tasks@: Tb666e6ce 2016-11-14T12:04:00-05:00 INFO: [10029] Creating new folder uuid for @Notes@: N6d6ecbe3 2016-11-14T12:04:00-05:00 INFO: [10029] Polling Horde_Core_ActiveSync_Driver::_getMailFolders() 2016-11-14T12:04:00-05:00 INFO: [10029] Creating new folder uuid for INBOX: Fe4d57a40
Now we send the folder tree to the client, along with a synckey (only showing one folder for brevity's sake):
2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:FolderSync> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:Status> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O 1 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:Status> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:SyncKey> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O {5829ee7f-b60c-405a-822f-272dc0a80160}1 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:SyncKey> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:Changes> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:Count> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O 87 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:Count> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:Add> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:ServerEntryId> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O Tb666e6ce 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:ServerEntryId> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:ParentId> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O 0 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:ParentId> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:DisplayName> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O Tasks 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:DisplayName> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O <FolderHierarchy:Type> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O 7 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:Type> 2016-11-14T12:04:00-05:00 DEBUG: [10029] O </FolderHierarchy:Add> 2016-11-14T12:04:01-05:00 DEBUG: [10029] O </FolderHierarchy:Changes> 2016-11-14T12:04:01-05:00 DEBUG: [10029] O </FolderHierarchy:FolderSync>
This is a good time to mention the SyncKey. The SyncKey is the unique identifier a specific set of state. It represents the state of the collection being synced at that point in time. It always has the following form:
{xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx}y where y is a continuously increasing counter. That increments any time changes are received from or sent to the client. The GUID-looking value in front of the counter will remain constant after it's generated for each collection.
Next, the client can issue SYNC requests for each folder it wants to populate. Unlike the FOLDERSYNC request, the SYNC request doesn't send the actual changes back with the 1st synckey. E.g., the first SYNC request for a mail folder contains some options such as the filtertype (how far back to sync), bodytype preferences etc... The server sets those options in the SyncCache for that collection, creates a new synckey, stores it in the collection's state and sends back the initial response.
2016-11-14T17:04:03+00:00 DEBUG: [10030] I <Synchronize> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <Folders> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <Folder> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <SyncKey> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 0 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </SyncKey> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <FolderId> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I Fe4d57a40 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </FolderId> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <Options> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <FilterType> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 5 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </FilterType> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:BodyPreference> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:Type> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 1 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:Type> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:Preview> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 128 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:Preview> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:BodyPreference> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:BodyPreference> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:Type> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 2 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:Type> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:Preview> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 128 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:Preview> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:BodyPreference> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <MIMESupport> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 1 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </MIMESupport> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:BodyPreference> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:Type> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 4 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:Type> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:TruncationSize> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 107520 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:TruncationSize> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <AirSyncBase:Preview> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 128 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:Preview> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </AirSyncBase:BodyPreference> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <Conflict> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 1 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </Conflict> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I <RightsManagement:RightsManagementSupport> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I 1 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </RightsManagement:RightsManagementSupport> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </Options> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </Folder> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </Folders> 2016-11-14T17:04:03+00:00 DEBUG: [10030] I </Synchronize> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <Synchronize> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <Status> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O 1 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </Status> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <Folders> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <Folder> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <SyncKey> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O {5829ee83-11e8-472d-bc66-272ec0a80160}1 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </SyncKey> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <FolderId> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O Fe4d57a40 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </FolderId> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O <Status> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O 1 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </Status> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </Folder> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </Folders> 2016-11-14T17:04:03+00:00 DEBUG: [10030] O </Synchronize>
Now, the next SYNC request for this folder will be sent with the SyncKey of {5829ee83-11e8-472d-bc66-272ec0a80160}1. At this point we know it's the "first sync" i.e., all objects are "new" from the client's point of view, so we do some optimizations and take advantage of this. Otherwise, all the future SYNC requests will behave the same way - the client sends the last SyncKey it knows about, the server uses that to get the state of whatever collection we are syncing, calculates the changes, increments the SyncKey counter, sends it all and saves the new state.
The general flow for getting server changes would be something like this:
In ActiveSync_Request_Sync::_handle() --->
call into Horde_ActiveSync_Collections::getCollectionChanges() --->
which calls into Horde_ActiveSync_State_Base::getChanges() --->
which finally calls Horde_Core_ActiveSync_Driver::getServerChanges() to get the changes.
Once we have the change set in H_AS_Request_Sync::_handle(), we set it into the exporter object the loop and send each change (see Horde_ActiveSync_Connector_Exporter_Sync::sendNextChange()).