Discussion:
Can't sync calendar & contacts, ActiveSync, horde4, android 4.0.2
(too old to reply)
Daniel Basa
2012-02-02 12:05:29 UTC
Permalink
Hi Horde list,

to cut a long story short:

I can't sync my calendar (contacts) with active sync using horde 4 and
android 4.0.2.
My Galaxy Nexus tells me there are no calendars. The synced contacts to
not show up in the address book.

Here comes the long story:

I have set up Horde Groupware Webmail Edition for use as a webmailer and
to sync calendars and contacts with mobile phones using ActiveSync
(android and iOS).
My server uses exim4 and dovecot. Horde is authenticating over imap, so
there are no horde specific users.
I am using apache 2.2.14 with FastCGI on Ubuntu 10.04. I had some
trouble getting the ActiveSync authentication to work
but found a solution for it on the horde mailinglists (and on the web
https://maurus.net/weblog/).
Authentication seems to work by now. My horde activesync.log sais the
following.

+----[ activesync.log ]
| 2012-01-31T17:44:17+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: username at domain.com
| 2012-01-31T17:44:18+01:00 DEBUG: [] OPTIONS request received for user
username at domain.com
+----------------------

After having some trouble where I could not see my device in the Device
Management section in the Active Sync settings I cleaned my MySQL tables
and connected again. The authentication succeeded and the device was
(is) displayed now in the Device Management section:

+----[ Device Management ]-------------------------------------------
+ Device | Last Sync Time | Status
+--------------------------------------------------------------------
+ Android | 31. Jan 2012 17:44 | Not Provisioned
+ | | Device id:androidc1771218180
+ | | Policy Key:0
+ | | User Agent:Android/4.0.2-EAS-1.3
+--------------------------------------------------------------------

Everything seems good from this point as far as I understand (don't know
what "not provisioned" means exactly and can't figure it out - I am not
a native speaker) but, I have trouble syncing my calendar. The Android
Calendar app does not show/find any Calendars. Syncing my Contacts does
not work either, though there are no error messages.

First I did an upgrade of horde (pear upgrade -a -B -c horde) at 17:47
UTC+1 on January the 31st 2012 and restarted apache but that changed
nothing.
I am running horde 4.0.13 now (atleast I am told that by the help button
from the horde webmail interface).

I searched the mailing list (the web too but nothing found there worked
out) and found two interesting threads

First:

Hanns Mattes device was not showing up in his active sync settings and
he got the following sync.log

,----[ /var/log/sync.log ]
| 2012-01-27T23:09:09+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 DEBUG: [] OPTIONS request received for user
hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 DEBUG: [androidc1405421619] FOLDERSYNC
request received for user hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 DEBUG: [androidc1405421619] loadDeviceInfo:
| 2012-01-27T23:09:09+01:00 DEBUG: Resetting PING state
| 2012-01-27T23:09:09+01:00 DEBUG: Resetting PING state
| 2012-01-27T23:09:09+01:00 DEBUG: [androidc1405421619] Device entry
does not exist for user

In the thread (By Hanns Mattes; Title: Activesync) he was given the
advice to make sure his database schema is up to date and to try
migrating the activesync tables down, then back up. i.e.:

$ horde-db-migrate /path/to/framework/ActiveSync/migration down

$ horde-db-migrate /path/to/framework/ActiveSync/migration up

I don't get such a log (see my log from above) but the aiding person
said that his log was correct (except for the double PING). Thought this
might be a clue?!

Second:

A thread by Martin Hochreiter with the title "ActiveSync | Android 3.2"

He had the sync working with android 2.3 but with android 3.2 it is
somehow broken and he gets only "no calendars" (from his calendar app I
guess - like me) after configuration. Unfortunately he has some problems
with the logging too and the thread ends with the next post. Giving no
solution for the sync problem (at least not for me).

Can somebody point me into the right direction or provide some insight
if he or she has had the same issue?

Many thanks in advance,
Daniel
Michael J Rubinsky
2012-02-02 14:47:35 UTC
Permalink
Post by Daniel Basa
Hi Horde list,
I can't sync my calendar (contacts) with active sync using horde 4 and
android 4.0.2.
My Galaxy Nexus tells me there are no calendars. The synced contacts to
not show up in the address book.
Have you told Horde which address book(s) and calendar(s) to use for
syncing? This is a user pref in each application.

FWIW, this is the exact device I use everyday without issue.
Post by Daniel Basa
I have set up Horde Groupware Webmail Edition for use as a webmailer and
to sync calendars and contacts with mobile phones using ActiveSync
(android and iOS).
My server uses exim4 and dovecot. Horde is authenticating over imap, so
there are no horde specific users.
I am using apache 2.2.14 with FastCGI on Ubuntu 10.04. I had some
trouble getting the ActiveSync authentication to work
but found a solution for it on the horde mailinglists (and on the web
https://maurus.net/weblog/).
Authentication seems to work by now. My horde activesync.log sais the
following.
FWIW, this issue is described right on the ActiveSync wiki page.
http://wiki.horde.org/ActiveSync Though I really don't understand why
the workaround is needed, our http client normalizes those header
names - but that's a problem for another day...
Post by Daniel Basa
+----[ activesync.log ]
| 2012-01-31T17:44:17+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: username at domain.com
| 2012-01-31T17:44:18+01:00 DEBUG: [] OPTIONS request received for user
username at domain.com
+----------------------
After having some trouble where I could not see my device in the Device
Management section in the Active Sync settings I cleaned my MySQL tables
and connected again. The authentication succeeded and the device was
+----[ Device Management ]-------------------------------------------
+ Device | Last Sync Time | Status
+--------------------------------------------------------------------
+ Android | 31. Jan 2012 17:44 | Not Provisioned
+ | | Device id:androidc1771218180
+ | | Policy Key:0
+ | | User Agent:Android/4.0.2-EAS-1.3
+--------------------------------------------------------------------
Everything seems good from this point as far as I understand (don't know
what "not provisioned" means exactly and can't figure it out - I am not
"not provisioned" means that that the Horde server does not control
the device's security policies and is unable to remote wipe the
device. It doesn't have any bearing on the device's ability to
syncronize (assuming you didn't configure Horde to require a
provisioned device).
Post by Daniel Basa
a native speaker) but, I have trouble syncing my calendar. The Android
Calendar app does not show/find any Calendars. Syncing my Contacts does
not work either, though there are no error messages.
First I did an upgrade of horde (pear upgrade -a -B -c horde) at 17:47
UTC+1 on January the 31st 2012 and restarted apache but that changed
nothing.
I am running horde 4.0.13 now (atleast I am told that by the help button
from the horde webmail interface).
I searched the mailing list (the web too but nothing found there worked
out) and found two interesting threads
Hanns Mattes device was not showing up in his active sync settings and
he got the following sync.log
,----[ /var/log/sync.log ]
| 2012-01-27T23:09:09+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 DEBUG: [] OPTIONS request received for user
hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 DEBUG: [androidc1405421619] FOLDERSYNC
request received for user hannsldap <at> hannsmattes.de
| 2012-01-27T23:09:09+01:00 DEBUG: Resetting PING state
| 2012-01-27T23:09:09+01:00 DEBUG: Resetting PING state
| 2012-01-27T23:09:09+01:00 DEBUG: [androidc1405421619] Device entry
does not exist for user
In the thread (By Hanns Mattes; Title: Activesync) he was given the
advice to make sure his database schema is up to date and to try
$ horde-db-migrate /path/to/framework/ActiveSync/migration down
$ horde-db-migrate /path/to/framework/ActiveSync/migration up
This was because his database schema was not up-to-date.
Post by Daniel Basa
I don't get such a log (see my log from above) but the aiding person
said that his log was correct (except for the double PING). Thought this
might be a clue?!
A thread by Martin Hochreiter with the title "ActiveSync | Android 3.2"
He had the sync working with android 2.3 but with android 3.2 it is
somehow broken and he gets only "no calendars" (from his calendar app I
guess - like me) after configuration. Unfortunately he has some problems
with the logging too and the thread ends with the next post. Giving no
solution for the sync problem (at least not for me).
Can somebody point me into the right direction or provide some insight
if he or she has had the same issue?
I will tell you what I tell everybody that asks about issues with
syncing; We need YOUR full synclog. I am unable to diagnose or
otherwise help you without seeing exactly what is being sent to and
from the device. Even better would be a synclog AND a wiretrace, but a
synclog would be the place to start. See the above mentioned wiki page
for instructions if you can't find the options for activesync logging
in the configuration.
--
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
Daniel Basa
2012-02-02 15:17:12 UTC
Permalink
Hi
Post by Michael J Rubinsky
Post by Daniel Basa
I can't sync my calendar (contacts) with active sync using horde 4 and
android 4.0.2.
My Galaxy Nexus tells me there are no calendars. The synced contacts to
not show up in the address book.
Have you told Horde which address book(s) and calendar(s) to use for
syncing? This is a user pref in each application.
If you mean by this going to the preference section and selecting
calendar (or address book) and hitting synchronization preferences there
in order to check the calendars (or address books) to sync then: yes. I
also tried to create another calendar as the default. Although as far as
i understood, the default calendar is enabled for syncing by default ...
Post by Michael J Rubinsky
Post by Daniel Basa
+----[ activesync.log ]
| 2012-01-31T17:44:17+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: username at domain.com
| 2012-01-31T17:44:18+01:00 DEBUG: [] OPTIONS request received for user
username at domain.com
+----------------------
Can somebody point me into the right direction or provide some insight
if he or she has had the same issue?
I will tell you what I tell everybody that asks about issues with
syncing; We need YOUR full synclog. I am unable to diagnose or otherwise
help you without seeing exactly what is being sent to and from the
device.
As long as there is no other setting which i can use to squeeze more out
of horde, what you see aboveis the abbreviated part of my complete sync
log. My settings for Active Sync Logging are as follows:

Logging
* $conf[activesync][logging][type] = Custom
* $conf[activesync][logging][path] = /path/to/activesync.log

Horde logging is set the debug, but the messages displayed there seem to
be associated with syncing. (new syncing does not provide new entries there)

I got no php errors

Here my complete activesync.log:
2012-01-13T08:28:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:28:15+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:28:32+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:28:41+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:35:30+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:35:39+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:44:53+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:45:02+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:48:34+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:48:44+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:49:50+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:50:00+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:50:42+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:50:51+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:52:54+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:53:03+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T08:58:47+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T08:58:56+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:18:12+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:18:21+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:20:52+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:21:01+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:22:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:22:15+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:30:18+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:30:27+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:32:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:32:15+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:35:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:35:15+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:36:40+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:36:49+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:38:44+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:38:53+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:42:10+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:42:20+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T09:52:15+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T09:52:24+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T10:18:07+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T10:18:16+01:00 DEBUG: [] OPTIONS request received for user
2012-01-13T10:26:39+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-13T10:26:48+01:00 DEBUG: [] OPTIONS request received for user
2012-01-31T15:05:13+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-31T15:05:22+01:00 DEBUG: [] OPTIONS request received for user
2012-01-31T15:07:40+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-31T15:07:49+01:00 DEBUG: [] OPTIONS request received for user
2012-01-31T15:09:51+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for:
2012-01-31T15:10:00+01:00 DEBUG: [] OPTIONS request received for user
2012-01-31T15:34:42+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at mydomain.de
2012-01-31T15:34:42+01:00 DEBUG: [] OPTIONS request received for user
daniel at mydomain.de
2012-01-31T16:15:20+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at mydomain.de
2012-01-31T16:15:20+01:00 DEBUG: [] OPTIONS request received for user
daniel at mydomain.de
2012-01-31T16:44:32+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at mydomain.de
2012-01-31T16:44:33+01:00 DEBUG: [] OPTIONS request received for user
daniel at mydomain.de
2012-01-31T17:23:36+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at mydomain.de
2012-01-31T17:23:37+01:00 DEBUG: [] OPTIONS request received for user
daniel at mydomain.de
2012-01-31T17:44:17+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at mydomain.de
2012-01-31T17:44:18+01:00 DEBUG: [] OPTIONS request received for user
daniel at mydomain.de
Post by Michael J Rubinsky
Even better would be a synclog AND a wiretrace, but a synclog
would be the place to start. See the above mentioned wiki page for
instructions if you can't find the options for activesync logging in the
configuration.
I don't know about wiretrace, but I will check out what it is and how
its done.

Thank you for your time and your patience.

Daniel
Michael J Rubinsky
2012-02-02 15:24:02 UTC
Permalink
Post by Daniel Basa
Hi
Post by Michael J Rubinsky
Post by Daniel Basa
I can't sync my calendar (contacts) with active sync using horde 4 and
android 4.0.2.
My Galaxy Nexus tells me there are no calendars. The synced contacts to
not show up in the address book.
Have you told Horde which address book(s) and calendar(s) to use for
syncing? This is a user pref in each application.
If you mean by this going to the preference section and selecting
calendar (or address book) and hitting synchronization preferences there
in order to check the calendars (or address books) to sync then: yes. I
also tried to create another calendar as the default. Although as far as
i understood, the default calendar is enabled for syncing by default ...
Post by Michael J Rubinsky
Post by Daniel Basa
+----[ activesync.log ]
| 2012-01-31T17:44:17+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: username at domain.com
| 2012-01-31T17:44:18+01:00 DEBUG: [] OPTIONS request received for user
username at domain.com
+----------------------
Can somebody point me into the right direction or provide some insight
if he or she has had the same issue?
I will tell you what I tell everybody that asks about issues with
syncing; We need YOUR full synclog. I am unable to diagnose or otherwise
help you without seeing exactly what is being sent to and from the
device.
As long as there is no other setting which i can use to squeeze more out
of horde, what you see aboveis the abbreviated part of my complete sync
Logging
* $conf[activesync][logging][type] = Custom
* $conf[activesync][logging][path] = /path/to/activesync.log
Horde logging is set the debug, but the messages displayed there seem to
be associated with syncing. (new syncing does not provide new entries there)
I got no php errors
You should have a device-specific log file in that same directory.
Named something like androidxxxxxxxxxx.log. That's where all the
entries go, once we know the device id. Otherwise, it's impossible to
debug a problem on a server with more than 1 or 2 devices actively
syncing :)

The log you posted below looks like it was from the default
activesync.log file, which would only receive messages when we don't
have a device_id.
Post by Daniel Basa
2012-01-13T08:28:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
<snip>
Post by Daniel Basa
Post by Michael J Rubinsky
Even better would be a synclog AND a wiretrace, but a synclog
would be the place to start. See the above mentioned wiki page for
instructions if you can't find the options for activesync logging in the
configuration.
I don't know about wiretrace, but I will check out what it is and how
its done.
Let's try the above mentioned device specific log first...
--
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
Daniel Basa
2012-02-02 21:18:42 UTC
Permalink
Post by Daniel Basa
As long as there is no other setting which i can use to squeeze more out
of horde, what you see aboveis the abbreviated part of my complete sync
Logging
* $conf[activesync][logging][type] = Custom
* $conf[activesync][logging][path] = /path/to/activesync.log
Horde logging is set the debug, but the messages displayed there seem to
be associated with syncing. (new syncing does not provide new entries there)
I got no php errors
You should have a device-specific log file in that same directory. Named
something like androidxxxxxxxxxx.log. That's where all the entries go,
once we know the device id. Otherwise, it's impossible to debug a
problem on a server with more than 1 or 2 devices actively syncing :)
The log you posted below looks like it was from the default
activesync.log file, which would only receive messages when we don't
have a device_id.
Post by Daniel Basa
2012-01-13T08:28:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
<snip>
Post by Daniel Basa
Post by Michael J Rubinsky
Even better would be a synclog AND a wiretrace, but a synclog
would be the place to start. See the above mentioned wiki page for
instructions if you can't find the options for activesync logging in the
configuration.
I don't know about wiretrace, but I will check out what it is and how
its done.
Let's try the above mentioned device specific log first...
Thank you very much. I simply overlooked the device specific logfile.
I checked that logfile. I am not sure what and when horde logs stuff to
this file. But my last sync attempts where today (2012-02-02), but
neither today or yesterday anything was written to this logfile. The
last entry is from th 31st of Jnuary 2012. I don't remember exactly what
I did that day, but I think I created new accounts on my phone several
times. Is it possible that horde just logs these first logon attempts?
I also recognized that there are lines indicating a sync of mail
(inbox). I don't want to sync mail using horde (thought that would not
work?). I am using z-push to sync/push mail.

Here's the log file. I think it's five times the same log for different
login attempts. But I am not sure so I didn't snip it.

2012-01-31T15:34:42+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at example.com
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] FOLDERSYNC request
received for user daniel at example.com
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Device entry does
not exist, creating it.
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Device entry does
not exist for user daniel at example.com, creating it.
2012-01-31T15:34:43+01:00 INFO: Request being handled for device:
androidc1771218180 Supporting protocol version: 2.5
2012-01-31T15:34:43+01:00 INFO: [Horde_ActiveSync::handleFolderSync]
Beginning FOLDERSYNC
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Checking policykey
for device Key: 0 User: daniel at example.com
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] loadDeviceInfo:
daniel at example.com
2012-01-31T15:34:43+01:00 DEBUG: Policykey: 0 verified.
2012-01-31T15:34:43+01:00 DEBUG: I <FolderHierarchy:FolderSync>
2012-01-31T15:34:43+01:00 DEBUG: I <FolderHierarchy:SyncKey>
2012-01-31T15:34:43+01:00 DEBUG: I 0
2012-01-31T15:34:43+01:00 DEBUG: I </FolderHierarchy:SyncKey>
2012-01-31T15:34:43+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
syncKey: 0
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Resetting device
state.
2012-01-31T15:34:43+01:00 DEBUG: I </FolderHierarchy:FolderSync>
2012-01-31T15:34:43+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
Preparing to send changes to PIM
2012-01-31T15:34:43+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
newSyncKey: {4f27fc03-61b8-486d-ab0a-3766551fbb0c}1
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Initializing
folder diff engine
2012-01-31T15:34:43+01:00 DEBUG: Horde::getFolderList()
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Found 4 folder changes
2012-01-31T15:34:43+01:00 DEBUG: Horde::getFolder(Tasks)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T15:34:43+01:00 DEBUG: Updating state during foldersync
2012-01-31T15:34:43+01:00 DEBUG: Horde::getFolder(Inbox)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T15:34:43+01:00 DEBUG: Updating state during foldersync
2012-01-31T15:34:43+01:00 DEBUG: Horde::getFolder(Contacts)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T15:34:43+01:00 DEBUG: Updating state during foldersync
2012-01-31T15:34:43+01:00 DEBUG: Horde::getFolder(Calendar)
2012-01-31T15:34:43+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T15:34:43+01:00 DEBUG: Updating state during foldersync
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:FolderSync>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Status>
2012-01-31T15:34:43+01:00 DEBUG: O 1
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Status/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:SyncKey>
2012-01-31T15:34:43+01:00 DEBUG: O
{4f27fc03-61b8-486d-ab0a-3766551fbb0c}1
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:SyncKey/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Changes>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Count>
2012-01-31T15:34:43+01:00 DEBUG: O 4
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Count/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T15:34:43+01:00 DEBUG: O Tasks
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T15:34:43+01:00 DEBUG: O 0
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T15:34:43+01:00 DEBUG: O Tasks
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T15:34:43+01:00 DEBUG: O 7
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T15:34:43+01:00 DEBUG: O Inbox
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T15:34:43+01:00 DEBUG: O 0
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T15:34:43+01:00 DEBUG: O Inbox
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T15:34:43+01:00 DEBUG: O 2
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T15:34:43+01:00 DEBUG: O Contacts
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T15:34:43+01:00 DEBUG: O 0
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T15:34:43+01:00 DEBUG: O Contacts
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T15:34:43+01:00 DEBUG: O 9
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T15:34:43+01:00 DEBUG: O Calendar
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T15:34:43+01:00 DEBUG: O 0
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T15:34:43+01:00 DEBUG: O Calendar
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T15:34:43+01:00 DEBUG: O 8
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:Changes/>
2012-01-31T15:34:43+01:00 DEBUG: O <FolderHierarchy:FolderSync/>
2012-01-31T15:34:43+01:00 DEBUG: [androidc1771218180] Saving state: Array
(
[0] => {4f27fc03-61b8-486d-ab0a-3766551fbb0c}1
[1] =>
a:4:{i:0;a:3:{s:2:"id";s:5:"Tasks";s:3:"mod";s:5:"Tasks";s:6:"parent";i:0;}i:1;a:3:{s:2:"id";s:5:"Inbox";s:3:"mod";s:5:"Inbox";s:6:"parent";i:0;}i:2;a:3:{s:2:"id";s:8:"Contacts";s:3:"mod";s:8:"Contacts";s:6:"parent";i:0;}i:3;a:3:{s:2:"id";s:8:"Calendar";s:3:"mod";s:8:"Calendar";s:6:"parent";i:0;}}
[2] => androidc1771218180
[3] => 1328020483
[4] => foldersync
[5] => daniel at example.com
)

2012-01-31T15:34:43+01:00 INFO: User daniel at example.com logged off
2012-01-31T16:15:21+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at example.com
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] FOLDERSYNC request
received for user daniel at example.com
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Device entry does
not exist, creating it.
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Device entry does
not exist for user daniel at example.com, creating it.
2012-01-31T16:15:21+01:00 INFO: Request being handled for device:
androidc1771218180 Supporting protocol version: 2.5
2012-01-31T16:15:21+01:00 INFO: [Horde_ActiveSync::handleFolderSync]
Beginning FOLDERSYNC
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Checking policykey
for device Key: 0 User: daniel at example.com
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] loadDeviceInfo:
daniel at example.com
2012-01-31T16:15:21+01:00 DEBUG: Policykey: 0 verified.
2012-01-31T16:15:21+01:00 DEBUG: I <FolderHierarchy:FolderSync>
2012-01-31T16:15:21+01:00 DEBUG: I <FolderHierarchy:SyncKey>
2012-01-31T16:15:21+01:00 DEBUG: I 0
2012-01-31T16:15:21+01:00 DEBUG: I </FolderHierarchy:SyncKey>
2012-01-31T16:15:21+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
syncKey: 0
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Resetting device
state.
2012-01-31T16:15:21+01:00 DEBUG: I </FolderHierarchy:FolderSync>
2012-01-31T16:15:21+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
Preparing to send changes to PIM
2012-01-31T16:15:21+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
newSyncKey: {4f280589-7144-4908-b72c-37c5551fbb0c}1
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Initializing
folder diff engine
2012-01-31T16:15:21+01:00 DEBUG: Horde::getFolderList()
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Found 4 folder changes
2012-01-31T16:15:21+01:00 DEBUG: Horde::getFolder(Tasks)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T16:15:21+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:15:21+01:00 DEBUG: Horde::getFolder(Inbox)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T16:15:21+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:15:21+01:00 DEBUG: Horde::getFolder(Contacts)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T16:15:21+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:15:21+01:00 DEBUG: Horde::getFolder(Calendar)
2012-01-31T16:15:21+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T16:15:21+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:FolderSync>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Status>
2012-01-31T16:15:21+01:00 DEBUG: O 1
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Status/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:SyncKey>
2012-01-31T16:15:21+01:00 DEBUG: O
{4f280589-7144-4908-b72c-37c5551fbb0c}1
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:SyncKey/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Changes>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Count>
2012-01-31T16:15:21+01:00 DEBUG: O 4
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Count/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:15:21+01:00 DEBUG: O Tasks
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:15:21+01:00 DEBUG: O 0
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:15:21+01:00 DEBUG: O Tasks
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:15:21+01:00 DEBUG: O 7
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:15:21+01:00 DEBUG: O Inbox
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:15:21+01:00 DEBUG: O 0
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:15:21+01:00 DEBUG: O Inbox
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:15:21+01:00 DEBUG: O 2
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:15:21+01:00 DEBUG: O Contacts
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:15:21+01:00 DEBUG: O 0
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:15:21+01:00 DEBUG: O Contacts
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:15:21+01:00 DEBUG: O 9
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:15:21+01:00 DEBUG: O Calendar
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:15:21+01:00 DEBUG: O 0
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:15:21+01:00 DEBUG: O Calendar
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:15:21+01:00 DEBUG: O 8
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:Changes/>
2012-01-31T16:15:21+01:00 DEBUG: O <FolderHierarchy:FolderSync/>
2012-01-31T16:15:21+01:00 DEBUG: [androidc1771218180] Saving state: Array
(
[0] => {4f280589-7144-4908-b72c-37c5551fbb0c}1
[1] =>
a:4:{i:0;a:3:{s:2:"id";s:5:"Tasks";s:3:"mod";s:5:"Tasks";s:6:"parent";i:0;}i:1;a:3:{s:2:"id";s:5:"Inbox";s:3:"mod";s:5:"Inbox";s:6:"parent";i:0;}i:2;a:3:{s:2:"id";s:8:"Contacts";s:3:"mod";s:8:"Contacts";s:6:"parent";i:0;}i:3;a:3:{s:2:"id";s:8:"Calendar";s:3:"mod";s:8:"Calendar";s:6:"parent";i:0;}}
[2] => androidc1771218180
[3] => 1328022921
[4] => foldersync
[5] => daniel at example.com
)

2012-01-31T16:15:21+01:00 INFO: User daniel at example.com logged off
2012-01-31T16:44:33+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at example.com
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] FOLDERSYNC request
received for user daniel at example.com
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Device entry does
not exist, creating it.
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Device entry does
not exist for user daniel at example.com, creating it.
2012-01-31T16:44:33+01:00 INFO: Request being handled for device:
androidc1771218180 Supporting protocol version: 2.5
2012-01-31T16:44:33+01:00 INFO: [Horde_ActiveSync::handleFolderSync]
Beginning FOLDERSYNC
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Checking policykey
for device Key: 0 User: daniel at example.com
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] loadDeviceInfo:
daniel at example.com
2012-01-31T16:44:33+01:00 DEBUG: Policykey: 0 verified.
2012-01-31T16:44:33+01:00 DEBUG: I <FolderHierarchy:FolderSync>
2012-01-31T16:44:33+01:00 DEBUG: I <FolderHierarchy:SyncKey>
2012-01-31T16:44:33+01:00 DEBUG: I 0
2012-01-31T16:44:33+01:00 DEBUG: I </FolderHierarchy:SyncKey>
2012-01-31T16:44:33+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
syncKey: 0
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Resetting device
state.
2012-01-31T16:44:33+01:00 DEBUG: I </FolderHierarchy:FolderSync>
2012-01-31T16:44:33+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
Preparing to send changes to PIM
2012-01-31T16:44:33+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
newSyncKey: {4f280c61-9c6c-45fe-989b-37c5551fbb0c}1
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Initializing
folder diff engine
2012-01-31T16:44:33+01:00 DEBUG: Horde::getFolderList()
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Found 4 folder changes
2012-01-31T16:44:33+01:00 DEBUG: Horde::getFolder(Tasks)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T16:44:33+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:44:33+01:00 DEBUG: Horde::getFolder(Inbox)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T16:44:33+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:44:33+01:00 DEBUG: Horde::getFolder(Contacts)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T16:44:33+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:44:33+01:00 DEBUG: Horde::getFolder(Calendar)
2012-01-31T16:44:33+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T16:44:33+01:00 DEBUG: Updating state during foldersync
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:FolderSync>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Status>
2012-01-31T16:44:33+01:00 DEBUG: O 1
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Status/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:SyncKey>
2012-01-31T16:44:33+01:00 DEBUG: O
{4f280c61-9c6c-45fe-989b-37c5551fbb0c}1
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:SyncKey/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Changes>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Count>
2012-01-31T16:44:33+01:00 DEBUG: O 4
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Count/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:44:33+01:00 DEBUG: O Tasks
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:44:33+01:00 DEBUG: O 0
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:44:33+01:00 DEBUG: O Tasks
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:44:33+01:00 DEBUG: O 7
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:44:33+01:00 DEBUG: O Inbox
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:44:33+01:00 DEBUG: O 0
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:44:33+01:00 DEBUG: O Inbox
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:44:33+01:00 DEBUG: O 2
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:44:33+01:00 DEBUG: O Contacts
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:44:33+01:00 DEBUG: O 0
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:44:33+01:00 DEBUG: O Contacts
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:44:33+01:00 DEBUG: O 9
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T16:44:33+01:00 DEBUG: O Calendar
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T16:44:33+01:00 DEBUG: O 0
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T16:44:33+01:00 DEBUG: O Calendar
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T16:44:33+01:00 DEBUG: O 8
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:Changes/>
2012-01-31T16:44:33+01:00 DEBUG: O <FolderHierarchy:FolderSync/>
2012-01-31T16:44:33+01:00 DEBUG: [androidc1771218180] Saving state: Array
(
[0] => {4f280c61-9c6c-45fe-989b-37c5551fbb0c}1
[1] =>
a:4:{i:0;a:3:{s:2:"id";s:5:"Tasks";s:3:"mod";s:5:"Tasks";s:6:"parent";i:0;}i:1;a:3:{s:2:"id";s:5:"Inbox";s:3:"mod";s:5:"Inbox";s:6:"parent";i:0;}i:2;a:3:{s:2:"id";s:8:"Contacts";s:3:"mod";s:8:"Contacts";s:6:"parent";i:0;}i:3;a:3:{s:2:"id";s:8:"Calendar";s:3:"mod";s:8:"Calendar";s:6:"parent";i:0;}}
[2] => androidc1771218180
[3] => 1328024673
[4] => foldersync
[5] => daniel at example.com
)

2012-01-31T16:44:33+01:00 INFO: User daniel at example.com logged off
2012-01-31T17:23:37+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at example.com
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] FOLDERSYNC request
received for user daniel at example.com
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Device entry does
not exist, creating it.
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Device entry does
not exist for user daniel at example.com, creating it.
2012-01-31T17:23:37+01:00 INFO: Request being handled for device:
androidc1771218180 Supporting protocol version: 2.5
2012-01-31T17:23:37+01:00 INFO: [Horde_ActiveSync::handleFolderSync]
Beginning FOLDERSYNC
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Checking policykey
for device Key: 0 User: daniel at example.com
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] loadDeviceInfo:
daniel at example.com
2012-01-31T17:23:37+01:00 DEBUG: Policykey: 0 verified.
2012-01-31T17:23:37+01:00 DEBUG: I <FolderHierarchy:FolderSync>
2012-01-31T17:23:37+01:00 DEBUG: I <FolderHierarchy:SyncKey>
2012-01-31T17:23:37+01:00 DEBUG: I 0
2012-01-31T17:23:37+01:00 DEBUG: I </FolderHierarchy:SyncKey>
2012-01-31T17:23:37+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
syncKey: 0
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Resetting device
state.
2012-01-31T17:23:37+01:00 DEBUG: I </FolderHierarchy:FolderSync>
2012-01-31T17:23:37+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
Preparing to send changes to PIM
2012-01-31T17:23:37+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
newSyncKey: {4f281589-33d8-42b4-9b8d-37c5551fbb0c}1
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Initializing
folder diff engine
2012-01-31T17:23:37+01:00 DEBUG: Horde::getFolderList()
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Found 4 folder changes
2012-01-31T17:23:37+01:00 DEBUG: Horde::getFolder(Tasks)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T17:23:37+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:23:37+01:00 DEBUG: Horde::getFolder(Inbox)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T17:23:37+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:23:37+01:00 DEBUG: Horde::getFolder(Contacts)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T17:23:37+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:23:37+01:00 DEBUG: Horde::getFolder(Calendar)
2012-01-31T17:23:37+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T17:23:37+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:FolderSync>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Status>
2012-01-31T17:23:37+01:00 DEBUG: O 1
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Status/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:SyncKey>
2012-01-31T17:23:37+01:00 DEBUG: O
{4f281589-33d8-42b4-9b8d-37c5551fbb0c}1
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:SyncKey/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Changes>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Count>
2012-01-31T17:23:37+01:00 DEBUG: O 4
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Count/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:23:37+01:00 DEBUG: O Tasks
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:23:37+01:00 DEBUG: O 0
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:23:37+01:00 DEBUG: O Tasks
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:23:37+01:00 DEBUG: O 7
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:23:37+01:00 DEBUG: O Inbox
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:23:37+01:00 DEBUG: O 0
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:23:37+01:00 DEBUG: O Inbox
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:23:37+01:00 DEBUG: O 2
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:23:37+01:00 DEBUG: O Contacts
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:23:37+01:00 DEBUG: O 0
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:23:37+01:00 DEBUG: O Contacts
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:23:37+01:00 DEBUG: O 9
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:23:37+01:00 DEBUG: O Calendar
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:23:37+01:00 DEBUG: O 0
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:23:37+01:00 DEBUG: O Calendar
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:23:37+01:00 DEBUG: O 8
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:Changes/>
2012-01-31T17:23:37+01:00 DEBUG: O <FolderHierarchy:FolderSync/>
2012-01-31T17:23:37+01:00 DEBUG: [androidc1771218180] Saving state: Array
(
[0] => {4f281589-33d8-42b4-9b8d-37c5551fbb0c}1
[1] =>
a:4:{i:0;a:3:{s:2:"id";s:5:"Tasks";s:3:"mod";s:5:"Tasks";s:6:"parent";i:0;}i:1;a:3:{s:2:"id";s:5:"Inbox";s:3:"mod";s:5:"Inbox";s:6:"parent";i:0;}i:2;a:3:{s:2:"id";s:8:"Contacts";s:3:"mod";s:8:"Contacts";s:6:"parent";i:0;}i:3;a:3:{s:2:"id";s:8:"Calendar";s:3:"mod";s:8:"Calendar";s:6:"parent";i:0;}}
[2] => androidc1771218180
[3] => 1328027017
[4] => foldersync
[5] => daniel at example.com
)

2012-01-31T17:23:37+01:00 INFO: User daniel at example.com logged off
2012-01-31T17:44:18+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: daniel at example.com
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] FOLDERSYNC request
received for user daniel at example.com
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] loadDeviceInfo:
daniel at example.com
2012-01-31T17:44:18+01:00 DEBUG: Resetting PING state
2012-01-31T17:44:18+01:00 INFO: Request being handled for device:
androidc1771218180 Supporting protocol version: 2.5
2012-01-31T17:44:18+01:00 INFO: [Horde_ActiveSync::handleFolderSync]
Beginning FOLDERSYNC
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] Checking policykey
for device Key: 0 User: daniel at example.com
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] loadDeviceInfo:
daniel at example.com
2012-01-31T17:44:18+01:00 DEBUG: Policykey: 0 verified.
2012-01-31T17:44:18+01:00 DEBUG: I <FolderHierarchy:FolderSync>
2012-01-31T17:44:18+01:00 DEBUG: I <FolderHierarchy:SyncKey>
2012-01-31T17:44:18+01:00 DEBUG: I 0
2012-01-31T17:44:18+01:00 DEBUG: I </FolderHierarchy:SyncKey>
2012-01-31T17:44:18+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
syncKey: 0
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] Resetting device
state.
2012-01-31T17:44:18+01:00 DEBUG: I </FolderHierarchy:FolderSync>
2012-01-31T17:44:18+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
Preparing to send changes to PIM
2012-01-31T17:44:18+01:00 DEBUG: [Horde_ActiveSync::handleFolderSync]
newSyncKey: {4f281a62-edfc-4242-8dfb-3ad2551fbb0c}1
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] Initializing
folder diff engine
2012-01-31T17:44:18+01:00 DEBUG: Horde::getFolderList()
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] Found 4 folder changes
2012-01-31T17:44:18+01:00 DEBUG: Horde::getFolder(Tasks)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Tasks)
2012-01-31T17:44:18+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:44:18+01:00 DEBUG: Horde::getFolder(Inbox)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Inbox)
2012-01-31T17:44:18+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:44:18+01:00 DEBUG: Horde::getFolder(Contacts)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Contacts)
2012-01-31T17:44:18+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:44:18+01:00 DEBUG: Horde::getFolder(Calendar)
2012-01-31T17:44:18+01:00 DEBUG: Horde::statFolder(Calendar)
2012-01-31T17:44:18+01:00 DEBUG: Updating state during foldersync
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:FolderSync>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Status>
2012-01-31T17:44:18+01:00 DEBUG: O 1
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Status/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:SyncKey>
2012-01-31T17:44:18+01:00 DEBUG: O
{4f281a62-edfc-4242-8dfb-3ad2551fbb0c}1
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:SyncKey/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Changes>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Count>
2012-01-31T17:44:18+01:00 DEBUG: O 4
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Count/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:44:18+01:00 DEBUG: O Tasks
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:44:18+01:00 DEBUG: O 0
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:44:18+01:00 DEBUG: O Tasks
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:44:18+01:00 DEBUG: O 7
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:44:18+01:00 DEBUG: O Inbox
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:44:18+01:00 DEBUG: O 0
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:44:18+01:00 DEBUG: O Inbox
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:44:18+01:00 DEBUG: O 2
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:44:18+01:00 DEBUG: O Contacts
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:44:18+01:00 DEBUG: O 0
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:44:18+01:00 DEBUG: O Contacts
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:44:18+01:00 DEBUG: O 9
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId>
2012-01-31T17:44:18+01:00 DEBUG: O Calendar
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ServerEntryId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId>
2012-01-31T17:44:18+01:00 DEBUG: O 0
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:ParentId/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName>
2012-01-31T17:44:18+01:00 DEBUG: O Calendar
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:DisplayName/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type>
2012-01-31T17:44:18+01:00 DEBUG: O 8
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Type/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Add/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:Changes/>
2012-01-31T17:44:18+01:00 DEBUG: O <FolderHierarchy:FolderSync/>
2012-01-31T17:44:18+01:00 DEBUG: [androidc1771218180] Saving state: Array
(
[0] => {4f281a62-edfc-4242-8dfb-3ad2551fbb0c}1
[1] =>
a:4:{i:0;a:3:{s:2:"id";s:5:"Tasks";s:3:"mod";s:5:"Tasks";s:6:"parent";i:0;}i:1;a:3:{s:2:"id";s:5:"Inbox";s:3:"mod";s:5:"Inbox";s:6:"parent";i:0;}i:2;a:3:{s:2:"id";s:8:"Contacts";s:3:"mod";s:8:"Contacts";s:6:"parent";i:0;}i:3;a:3:{s:2:"id";s:8:"Calendar";s:3:"mod";s:8:"Calendar";s:6:"parent";i:0;}}
[2] => androidc1771218180
[3] => 1328028258
[4] => foldersync
[5] => daniel at example.com
)

2012-01-31T17:44:18+01:00 INFO: User daniel at example.com logged off
Michael J Rubinsky
2012-02-02 22:16:51 UTC
Permalink
Post by Daniel Basa
Post by Daniel Basa
As long as there is no other setting which i can use to squeeze more out
of horde, what you see aboveis the abbreviated part of my complete sync
Logging
* $conf[activesync][logging][type] = Custom
* $conf[activesync][logging][path] = /path/to/activesync.log
Horde logging is set the debug, but the messages displayed there seem to
be associated with syncing. (new syncing does not provide new entries there)
I got no php errors
You should have a device-specific log file in that same directory. Named
something like androidxxxxxxxxxx.log. That's where all the entries go,
once we know the device id. Otherwise, it's impossible to debug a
problem on a server with more than 1 or 2 devices actively syncing :)
The log you posted below looks like it was from the default
activesync.log file, which would only receive messages when we don't
have a device_id.
Post by Daniel Basa
2012-01-13T08:28:06+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
<snip>
Post by Daniel Basa
Post by Michael J Rubinsky
Even better would be a synclog AND a wiretrace, but a synclog
would be the place to start. See the above mentioned wiki page for
instructions if you can't find the options for activesync logging in the
configuration.
I don't know about wiretrace, but I will check out what it is and how
its done.
Let's try the above mentioned device specific log first...
Thank you very much. I simply overlooked the device specific logfile.
I checked that logfile. I am not sure what and when horde logs stuff to
this file.
It logs EVERY bit of of the protocol between the device and the
server, so anytime your device connects to Horde, something gets logged.
Post by Daniel Basa
But my last sync attempts where today (2012-02-02), but
neither today or yesterday anything was written to this logfile.
Then your device is not communicating with Horde. It could be that
something caused it to stop trying, or it could be that either the
device or Horde is not configured properly.
Post by Daniel Basa
The
last entry is from th 31st of Jnuary 2012. I don't remember exactly what
I did that day, but I think I created new accounts on my phone several
times. Is it possible that horde just logs these first logon attempts?
No.
Post by Daniel Basa
I also recognized that there are lines indicating a sync of mail
(inbox).
This is a fake syncronization attempt for email. It is necessary for
the device to think that email is syncing properly since a number of
devices (including the Galaxy Nexus) will not send meeting request
messages if the INBOX is not syncing. Nothing is polled on the IMAP
server.
Post by Daniel Basa
I don't want to sync mail using horde (thought that would not
work?). I am using z-push to sync/push mail.
Correct. Horde currently does not support email synchronization via
activesync. This was left out originally for a variety of reasons -
including the fact that the native email support in most devices is
far superior to what activesync can provide. That being said, we are
working on getting this implemented for Horde 4.1 which will be out in
May.

I'm curious as to why you feel ZPush's email support provides a better
experience than either Android's native client, or an app like K-9 mail?

Anyway, how did you configure ZPush and Horde? Hopefully on either
different (sub)domains. If you configured your device with two
different exchange accounts, both pointing at the same server, this
will cause lots of problems.
Post by Daniel Basa
Here's the log file. I think it's five times the same log for different
login attempts. But I am not sure so I didn't snip it.
The device is connecting, getting the list of folders/collections to
sync and then disconnecting. That part is normal. What's not normal
though is that it never attempts to connect again for the next step in
the process, the initial SYNC command. The only things I can think of
that would cause this are some type of corrupt data being sent to the
device (does not look like it from the logs, though a wiretrace would
be needed to rule that out), the device is not set to actively push
contacts/calendar for this account, or something is conflicting
between your ZPush and Horde setups.

Past that, I'm out of ideas, unless you want to provide a network
trace. Maybe somthing will show up there.

Oh, one more thing - you didn't by any chance turn off the email sync
for this account on the device did you? For this device (or maybe for
ICS in general), this is REQUIRED to be enabled, otherwise even if you
have enabled calendar and contacts the device will never perform the
initial SYNC - which it doesn't seem to be doing... I think I have a
note about that on the wiki page I referred you to earlier.

<snip>
--
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
Daniel Basa
2012-02-03 06:16:16 UTC
Permalink
Post by Michael J Rubinsky
Post by Daniel Basa
I don't want to sync mail using horde (thought that would not
work?). I am using z-push to sync/push mail.
I'm curious as to why you feel ZPush's email support provides a better
experience than either Android's native client, or an app like K-9 mail?
I am using K-9 mail. But I don't want to check email every now and then.
I would like to receive email when it's delivered to my mailbox. Z-Push
pushes the mail to my phone. I don't have to initialize checks for new
mails from my phone on a regular basis.
Post by Michael J Rubinsky
Anyway, how did you configure ZPush and Horde? Hopefully on either
different (sub)domains. If you configured your device with two different
exchange accounts, both pointing at the same server, this will cause
lots of problems.
Yep, I took care of that. Z-Push is running on the "subdomain handling
the mail-traffic" (mail.example.org). Horde is set to work on the
webmail sub-domain.
Post by Michael J Rubinsky
Past that, I'm out of ideas, unless you want to provide a network trace.
Maybe somthing will show up there.
Oh, one more thing - you didn't by any chance turn off the email sync
for this account on the device did you? For this device (or maybe for
ICS in general), this is REQUIRED to be enabled, otherwise even if you
have enabled calendar and contacts the device will never perform the
initial SYNC - which it doesn't seem to be doing... I think I have a
note about that on the wiki page I referred you to earlier.
You are hitting the nail on the head (At least in Germany we would say
so). After having the trouble with the device not showing up in the
device list I disabled E-Mail-syncing. Just to investigate the problem
on my own and play with some settings. The idea was to try on my own
before I ask someone else. Well, seems like it worked out the other way.
I did ask someone else and I am the blockhead now.
Sorry for bothering you with this.
I reenabled E-Mail syncing and readded the exchange account on my phone
once more and voila: It is working! Syncing calendar and contacts. The
only thing is that I can't see other calendars on my phone than the
default although they are enabled for syncing, but thats another story.
So now I can say good-bye to google and backup my contacts online (Never
gave them to mighty google ...)

I am very thankful for your help and I am sorry for me being such a
blockhead.

Thanks,

Daniel

P.S. You are right, it is on the wiki! *shame*
Michael M Slusarz
2012-02-03 09:06:39 UTC
Permalink
Post by Daniel Basa
Post by Michael J Rubinsky
Post by Daniel Basa
I don't want to sync mail using horde (thought that would not
work?). I am using z-push to sync/push mail.
I'm curious as to why you feel ZPush's email support provides a better
experience than either Android's native client, or an app like K-9 mail?
I am using K-9 mail. But I don't want to check email every now and then.
I would like to receive email when it's delivered to my mailbox. Z-Push
pushes the mail to my phone. I don't have to initialize checks for new
mails from my phone on a regular basis.
IMAP has done this forever - this is the IDLE extension
(http://tools.ietf.org/html/rfc2177). K-9 supports this.

michael

___________________________________
Michael Slusarz [slusarz at horde.org]
Michael J Rubinsky
2012-02-03 13:32:48 UTC
Permalink
Post by Michael J Rubinsky
Post by Michael J Rubinsky
Post by Daniel Basa
I don't want to sync mail using horde (thought that would not
work?). I am using z-push to sync/push mail.
I'm curious as to why you feel ZPush's email support provides a
better
Post by Michael J Rubinsky
experience than either Android's native client, or an app like K-9
mail?
I am using K-9 mail. But I don't want to check email every now and then.
I would like to receive email when it's delivered to my mailbox. Z-Push
pushes the mail to my phone. I don't have to initialize checks for new
mails from my phone on a regular basis.
Post by Michael J Rubinsky
Anyway, how did you configure ZPush and Horde? Hopefully on either
different (sub)domains. If you configured your device with two
different
Post by Michael J Rubinsky
exchange accounts, both pointing at the same server, this will cause
lots of problems.
Yep, I took care of that. Z-Push is running on the "subdomain handling
the mail-traffic" (mail.example.org). Horde is set to work on the
webmail sub-domain.
Post by Michael J Rubinsky
Past that, I'm out of ideas, unless you want to provide a network
trace.
Post by Michael J Rubinsky
Maybe somthing will show up there.
Oh, one more thing - you didn't by any chance turn off the email sync
for this account on the device did you? For this device (or maybe for
ICS in general), this is REQUIRED to be enabled, otherwise even if
you
Post by Michael J Rubinsky
have enabled calendar and contacts the device will never perform the
initial SYNC - which it doesn't seem to be doing... I think I have a
note about that on the wiki page I referred you to earlier.
You are hitting the nail on the head (At least in Germany we would say
so). After having the trouble with the device not showing up in the
device list I disabled E-Mail-syncing. Just to investigate the problem
on my own and play with some settings. The idea was to try on my own
before I ask someone else. Well, seems like it worked out the other way.
I did ask someone else and I am the blockhead now.
Sorry for bothering you with this.
I reenabled E-Mail syncing and readded the exchange account on my phone
once more and voila: It is working! Syncing calendar and contacts. The
only thing is that I can't see other calendars on my phone than the
default although they are enabled for syncing, but thats another story.
So now I can say good-bye to google and backup my contacts online (Never
gave them to mighty google ...)
I am very thankful for your help and I am sorry for me being such a
blockhead.
Thanks,
Daniel
P.S. You are right, it is on the wiki! *shame*
FWIW K9 mail does push email you just have to tell it to in the account settings. I've been using it that way for years.
mike
--
Sent from mobile

Continue reading on narkive:
Loading...