[horde] Active Sync - new calnedar entry [SOLVED]

Martin Hochreiter linuxbox at wavenet.at
Mon Aug 1 18:57:02 UTC 2011 

>
> 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):

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>

More information about the horde mailing list