[horde] Active Sync - new calnedar entry [SOLVED]
Michael J Rubinsky
mrubinsk at horde.org
Mon Aug 1 19:13:18 UTC 2011
Quoting Martin Hochreiter <linuxbox at wavenet.at>:
>>
>> Can you provide the offending event, or do you know where it was
>> failing so we can try to prevent this? If it's the device that
>> doesn't like the event, we can try to make it happier, but would
>> need a trace to see exactly what the client is sending back to
>> notify Horde of the error.
>>
>>
>>
> Unfortunately I had to delete the event in kronolith to make it
> working - and can not reproduce it by simply adding it. I only have
> that debug.log - it is the 18.01.2010 birthday event ... maybe that
> helps you (and I hope I have cut the right peace in the need length):
This log shows an event coming FROM the client to the server the
server adding it, and then sending the UID back to the client to show
that it was successfully added. I thought it was an event on the
server that was causing the problem?
> 2011-08-01T13:18:06+02:00 DEBUG: O <Folders/>
> 2011-08-01T13:18:06+02:00 DEBUG: O <Synchronize/>
> 2011-08-01T13:18:06+02:00 INFO: User martin_hochreiter logged off
> 2011-08-01T13:20:33+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for: martin_hochreiter
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> SYNC request received for user martin_hochreiter
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> loadDeviceInfo: martin_hochreiter
> 2011-08-01T13:20:34+02:00 DEBUG: Resetting PING state
> 2011-08-01T13:20:34+02:00 INFO: Request being handled for device:
> D07C514FE4229142CC2053896751894A Supporting protocol version: 2.5
> 2011-08-01T13:20:34+02:00 INFO: [D07C514FE4229142CC2053896751894A]
> Handling SYNC command.
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Checking policykey for device Key: 9381015523 User: martin_hochreiter
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> loadDeviceInfo: martin_hochreiter
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Stored key: 9381015523
> 2011-08-01T13:20:34+02:00 DEBUG: Policykey: 9381015523 verified.
> 2011-08-01T13:20:34+02:00 DEBUG: I <Synchronize>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Folders>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Folder>
> 2011-08-01T13:20:34+02:00 DEBUG: I <FolderType>
> 2011-08-01T13:20:34+02:00 DEBUG: I Calendar
> 2011-08-01T13:20:34+02:00 INFO: [D07C514FE4229142CC2053896751894A]
> Syncing folder class: Calendar
> 2011-08-01T13:20:34+02:00 DEBUG: I </FolderType>
> 2011-08-01T13:20:34+02:00 DEBUG: I <SyncKey>
> 2011-08-01T13:20:34+02:00 DEBUG: I
> {4e368b3b-e570-4d70-a58a-3ccfc0a80168}2
> 2011-08-01T13:20:34+02:00 DEBUG: I </SyncKey>
> 2011-08-01T13:20:34+02:00 DEBUG: I <FolderId>
> 2011-08-01T13:20:34+02:00 DEBUG: I Calendar
> 2011-08-01T13:20:34+02:00 INFO: [D07C514FE4229142CC2053896751894A]
> Folder server id: Calendar
> 2011-08-01T13:20:34+02:00 DEBUG: I </FolderId>
> 2011-08-01T13:20:34+02:00 DEBUG: I <DeletesAsMoves/>
> 2011-08-01T13:20:34+02:00 DEBUG: I <GetChanges/>
> 2011-08-01T13:20:34+02:00 DEBUG: I <WindowSize>
> 2011-08-01T13:20:34+02:00 DEBUG: I 100
> 2011-08-01T13:20:34+02:00 DEBUG: I </WindowSize>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Options>
> 2011-08-01T13:20:34+02:00 DEBUG: I <FilterType>
> 2011-08-01T13:20:34+02:00 DEBUG: I 0
> 2011-08-01T13:20:34+02:00 DEBUG: I </FilterType>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Truncation>
> 2011-08-01T13:20:34+02:00 DEBUG: I 6
> 2011-08-01T13:20:34+02:00 DEBUG: I </Truncation>
> 2011-08-01T13:20:34+02:00 DEBUG: I <RtfTruncation>
> 2011-08-01T13:20:34+02:00 DEBUG: I 6
> 2011-08-01T13:20:34+02:00 DEBUG: I </RtfTruncation>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Conflict>
> 2011-08-01T13:20:34+02:00 DEBUG: I 1
> 2011-08-01T13:20:34+02:00 DEBUG: I </Conflict>
> 2011-08-01T13:20:34+02:00 DEBUG: I </Options>
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Loading state for synckey {4e368b3b-e570-4d70-a58a-3ccfc0a80168}2
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> SQL query by Horde_ActiveSync_State:_gc(): SELECT sync_key FROM
> horde_activesync_state WHERE sync_devid = ? AND sync_folderid = ?
> VALUES: Array
> (
> [0] => D07C514FE4229142CC2053896751894A
> [1] => Calendar
> )
>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Commands>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Add>
> 2011-08-01T13:20:34+02:00 DEBUG: I <ClientEntryId>
> 2011-08-01T13:20:34+02:00 DEBUG: I 1073744522
> 2011-08-01T13:20:34+02:00 DEBUG: I </ClientEntryId>
> 2011-08-01T13:20:34+02:00 DEBUG: I <Data>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:Timezone>
> 2011-08-01T13:20:34+02:00 DEBUG: I
> xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAAFAAIAAAAAAAAAxP///w==
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:Timezone>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:AllDayEvent>
> 2011-08-01T13:20:34+02:00 DEBUG: I 0
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:AllDayEvent>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:BusyStatus>
> 2011-08-01T13:20:34+02:00 DEBUG: I 2
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:BusyStatus>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:Rtf/>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:DtStamp>
> 2011-08-01T13:20:34+02:00 DEBUG: I 20110801T111803Z
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:DtStamp>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:EndTime>
> 2011-08-01T13:20:34+02:00 DEBUG: I 20100118T210000Z
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:EndTime>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:MeetingStatus>
> 2011-08-01T13:20:34+02:00 DEBUG: I 0
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:MeetingStatus>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:OrganizerEmail>
> 2011-08-01T13:20:34+02:00 DEBUG: I martin.hochreiter at rk-lilienfeld.at
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:OrganizerEmail>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:OrganizerName>
> 2011-08-01T13:20:34+02:00 DEBUG: I Martin Hochreiter (OERK-N LF)
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:OrganizerName>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:Sensitivity>
> 2011-08-01T13:20:34+02:00 DEBUG: I 0
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:Sensitivity>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:Subject>
> 2011-08-01T13:20:34+02:00 DEBUG: I Ina Geburtstag
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:Subject>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:StartTime>
> 2011-08-01T13:20:34+02:00 DEBUG: I 20100118T210000Z
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:StartTime>
> 2011-08-01T13:20:34+02:00 DEBUG: I <POOMCAL:UID>
> 2011-08-01T13:20:34+02:00 DEBUG: I 0A000D0F93048C929B5F5F10
> 2011-08-01T13:20:34+02:00 DEBUG: I </POOMCAL:UID>
> 2011-08-01T13:20:34+02:00 DEBUG: I </Data>
> 2011-08-01T13:20:34+02:00 DEBUG: Horde::changeMessage(Calendar, )
> 2011-08-01T13:20:34+02:00 DEBUG:
> ActiveSync_Driver_Horde::_smartStatMessage:Calendar:20110801132034.KSUvGPGiLWVONowCPiIECTA at www.rk-lilienfeld.at
> 2011-08-01T13:20:34+02:00 DEBUG: I </Add>
> 2011-08-01T13:20:34+02:00 DEBUG: I </Commands>
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Processed 1 incoming changes
> 2011-08-01T13:20:34+02:00 DEBUG: I </Folder>
> 2011-08-01T13:20:34+02:00 DEBUG: I </Folders>
> 2011-08-01T13:20:34+02:00 DEBUG: I </Synchronize>
> 2011-08-01T13:20:34+02:00 INFO: [D07C514FE4229142CC2053896751894A]
> Beginning SYNC Response.
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Initializing message diff engine for Calendar
> 2011-08-01T13:20:34+02:00 DEBUG:
> Horde_ActiveSync_Driver_Horde::getServerChanges(Calendar,
> 1312197484, 1312197634, 0)
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Found 0 message changes, checking for PIM initiated changes.
> 2011-08-01T13:20:34+02:00 DEBUG: O <Synchronize>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Folders>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Folder>
> 2011-08-01T13:20:34+02:00 DEBUG: O <FolderType>
> 2011-08-01T13:20:34+02:00 DEBUG: O Calendar
> 2011-08-01T13:20:34+02:00 DEBUG: O <FolderType/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <SyncKey>
> 2011-08-01T13:20:34+02:00 DEBUG: O
> {4e368b3b-e570-4d70-a58a-3ccfc0a80168}3
> 2011-08-01T13:20:34+02:00 DEBUG: O <SyncKey/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <FolderId>
> 2011-08-01T13:20:34+02:00 DEBUG: O Calendar
> 2011-08-01T13:20:34+02:00 DEBUG: O <FolderId/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Status>
> 2011-08-01T13:20:34+02:00 DEBUG: O 1
> 2011-08-01T13:20:34+02:00 DEBUG: O <Status/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Replies>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Add>
> 2011-08-01T13:20:34+02:00 DEBUG: O <ClientEntryId>
> 2011-08-01T13:20:34+02:00 DEBUG: O 1073744522
> 2011-08-01T13:20:34+02:00 DEBUG: O <ClientEntryId/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <ServerEntryId>
> 2011-08-01T13:20:34+02:00 DEBUG: O
> 20110801132034.KSUvGPGiLWVONowCPiIECTA at www.rk-lilienfeld.at
> 2011-08-01T13:20:34+02:00 DEBUG: O <ServerEntryId/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Status>
> 2011-08-01T13:20:34+02:00 DEBUG: O 1
> 2011-08-01T13:20:34+02:00 DEBUG: O <Status/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Add/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Replies/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Folder/>
> 2011-08-01T13:20:34+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Saving state: Array
> (
> [0] => {4e368b3b-e570-4d70-a58a-3ccfc0a80168}3
> [1] => a:0:{}
> [2] => D07C514FE4229142CC2053896751894A
> [3] => 1312197634
> [4] => Calendar
> [5] => martin_hochreiter
> )
>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Folders/>
> 2011-08-01T13:20:34+02:00 DEBUG: O <Synchronize/>
> 2011-08-01T13:20:34+02:00 INFO: User martin_hochreiter logged off
> 2011-08-01T13:21:15+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for:
> 2011-08-01T13:21:25+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> GETITEMESTIMATE request received for user
> 2011-08-01T13:21:25+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> loadDeviceInfo:
> 2011-08-01T13:21:25+02:00 DEBUG: Resetting PING state
> 2011-08-01T13:21:25+02:00 DEBUG: Resetting PING state
> 2011-08-01T13:21:25+02:00 INFO: Request being handled for device:
> D07C514FE4229142CC2053896751894A Supporting protocol version: 2.5
> 2011-08-01T13:21:25+02:00 INFO: [D07C514FE4229142CC2053896751894A]
> Beginning GETITEMESTIMATE
> 2011-08-01T13:21:25+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Checking policykey for device Key: 9381015523 User:
> 2011-08-01T13:21:25+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> loadDeviceInfo:
> 2011-08-01T13:21:25+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> Stored key: 0
> 2011-08-01T13:21:25+02:00 INFO: User martin_hochreiter logged off
> 2011-08-01T13:21:26+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for:
> 2011-08-01T13:21:36+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> PROVISION request received for user
> 2011-08-01T13:21:36+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> loadDeviceInfo:
> 2011-08-01T13:21:36+02:00 DEBUG: Resetting PING state
> 2011-08-01T13:21:36+02:00 DEBUG: Resetting PING state
> 2011-08-01T13:21:36+02:00 INFO: Request being handled for device:
> D07C514FE4229142CC2053896751894A Supporting protocol version: 2.5
> 2011-08-01T13:21:36+02:00 DEBUG: I <Provision:Provision>
> 2011-08-01T13:21:36+02:00 DEBUG: I <Provision:Policies>
> 2011-08-01T13:21:36+02:00 DEBUG: I <Provision:Policy>
> 2011-08-01T13:21:36+02:00 DEBUG: I <Provision:PolicyType>
> 2011-08-01T13:21:36+02:00 DEBUG: I MS-WAP-Provisioning-XML
> 2011-08-01T13:21:36+02:00 DEBUG: I </Provision:PolicyType>
> 2011-08-01T13:21:36+02:00 DEBUG: I </Provision:Policy>
> 2011-08-01T13:21:36+02:00 DEBUG: I </Provision:Policies>
> 2011-08-01T13:21:36+02:00 DEBUG: I </Provision:Provision>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Provision>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Status>
> 2011-08-01T13:21:36+02:00 DEBUG: O 1
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Status/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Policies>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Policy>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:PolicyType>
> 2011-08-01T13:21:36+02:00 DEBUG: O MS-WAP-Provisioning-XML
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:PolicyType/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Status>
> 2011-08-01T13:21:36+02:00 DEBUG: O 1
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Status/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:PolicyKey>
> 2011-08-01T13:21:36+02:00 DEBUG: O 8695619766
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:PolicyKey/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Data>
> 2011-08-01T13:21:36+02:00 DEBUG: O
> <wap-provisioningdoc><characteristic type="SecurityPolicy"><parm
> name="4131" value="1"/><parm name="4133"
> value="1"/></characteristic><characteristic
> type="Registry"><characteristic
> type="HKLM\Comm\Security\Policy\LASSD\AE\{50C13377-C66D-400C-889E-C316FC4AB374}"><parm name="AEFrequencyType" value="1"/></characteristic><characteristic type="HKLM\Comm\Security\Policy\LASSD"><parm name="DeviceWipeThreshold" value="10"/></characteristic><characteristic type="HKLM\Comm\Security\Policy\LASSD"><parm name="CodewordFrequency" value="5"/></characteristic><characteristic type="HKLM\Comm\Security\Policy\LASSD\LAP\lap_pw"><parm name="MinimumPasswordLength" value="5"/></characteristic><characteristic type="HKLM\Comm\Security\Policy\LASSD\LAP\lap_pw"><parm name="PasswordComplexity"
> value="2"/></characteristic></characteristic></wap-provisioningdoc>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Data/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Policy/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Policies/>
> 2011-08-01T13:21:36+02:00 DEBUG: O <Provision:Provision/>
> 2011-08-01T13:21:36+02:00 INFO: User martin_hochreiter logged off
> 2011-08-01T13:21:37+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for: martin_hochreiter
> 2011-08-01T13:21:37+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> PROVISION request received for user martin_hochreiter
> 2011-08-01T13:21:37+02:00 DEBUG: [D07C514FE4229142CC2053896751894A]
> loadDeviceInfo: martin_hochreiter
> 2011-08-01T13:21:37+02:00 DEBUG: Resetting PING state
> 2011-08-01T13:21:37+02:00 INFO: Request being handled for device:
> D07C514FE4229142CC2053896751894A Supporting protocol version: 2.5
> 2011-08-01T13:21:37+02:00 DEBUG: I <Provision:Provision>
> 2011-08-01T13:21:37+02:00 DEBUG: I <Provision:Policies>
--
mike
The Horde Project (www.horde.org)
mrubinsk at horde.org
More information about the horde
mailing list