View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0006069SOGoActiveSyncpublic2025-01-10 13:272025-01-10 13:27
Reporterleecher Assigned To 
PrioritynormalSeveritymajorReproducibilityunable to reproduce
Status newResolutionopen 
Platform[Client] MicrosoftOSWindowsOS Version7
Product Version5.10.0 
Summary0006069: Updating Calendar item in EAS client, it sometimes replies with status 8, even though object is present
Description

From time to time (every few days), there are problems when changing calendar entries, however it is not reproducable.
The EAS client requests a change on an existing Calendar entry and the server - instead of changing the entry - responds with status code 8 (Object Not Found).
However the object clearly exists in the database and also shows up in the web calendar and a change a few minutes before the event using the same client was successful and there was no delete operation in between.
As such errors happen sporadically, how to diagnose the reason for the error in such a case?
The log doesn't give us a reason why object wasn't found.
The error is really serious, becase the client (i.e. MS Outlook in this case) decides to delete the item when receiving status 8 whereas other clients still have the item available (as it clearly exists) leading to confusion.
In case these are database backend access errors, are these logged somewhere? I didn't see any in the mysql syslog at the given point in time.

Steps To Reproduce

Change a calendar items multiple times, sometimes it may think that the item got removed.
I attached a log file clearly shwing the proces. at 12:27 the item was changed by the same client, got back status 0 and happily broadcasted the changes to the clients (omitted in the log, as it's not important in this case).
Then on 12:37 the client changed the same item again (no reference to the item was found in between that would indicate a change or deletion by another client).
Then it returned error 8.
In the sourcecode, I that this happens when any kind of exception occurs when accessing the object? However, there is no information in the log about the exception.
I'm also willing to recompile from source if you can tell me which code to add to track down the reason for the exception.

TagsNo tags attached.

Activities

leecher

leecher

2025-01-10 13:27

reporter  

sogo-log-err-itemdel.txt (8,368 bytes)    
1. Change request at 12:27
-----------------------

Jan 10 12:27:05 sogod [20431]: <0x0x556dee1816c0[SOGoActiveSyncDispatcher]> EAS - request for device C9CF64644D1944D8A560D03F7C153DB8: <?xml version="1.0"?>
<!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
<Sync xmlns="AirSync:">
 <Collections>
  <Collection>
   <SyncKey>1736506203</SyncKey>
   <CollectionId>vevent%2Fpersonal</CollectionId>
   <DeletesAsMoves>0</DeletesAsMoves>
   <GetChanges>0</GetChanges>
   <WindowSize>512</WindowSize>
   <Options>
    <FilterType>0</FilterType>
    <BodyPreference xmlns="AirSyncBase:">
     <Type>1</Type>
     <AllOrNone>1</AllOrNone>
    </BodyPreference>
   </Options>
   <Commands>
    <Change>
     <ServerId>290B-677FE580-31-122BB540</ServerId>
     <ApplicationData>
      <TimeZone xmlns="Calendar:">xP///00AaQB0AHQAZQBsAGUAdQByAG8AcADkAGkAcwBjAGgAZQAgAFoAZQBpAHQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAE0AaQB0AHQAZQBsAGUAdQByAG8AcADkAGkAcwBjAGgAZQAgAFMAbwBtAG0AZQByAHoAZQBpAHQAAAAAAAAAAAAA
      <DTStamp xmlns="Calendar:">20250110T112707Z</DTStamp>
      <StartTime xmlns="Calendar:">20250212T110000Z</StartTime>
      <Subject xmlns="Calendar:">Mittagessen Dagobert Duck</Subject>
      <UID xmlns="Calendar:">040000008200E00074C5B7101A82E00800000000F07EF645B062DB01000000000000000010000000AAEB3FBBDEAF2A46A6B6D5038B9032E8</UID>
      <EndTime xmlns="Calendar:">20250212T130000Z</EndTime>
      <Categories xmlns="Calendar:">
       <Category>JP</Category>
      </Categories>
      <Sensitivity xmlns="Calendar:">0</Sensitivity>
      <BusyStatus xmlns="Calendar:">2</BusyStatus>
      <AllDayEvent xmlns="Calendar:">0</AllDayEvent>
      <Reminder xmlns="Calendar:">10</Reminder>
      <MeetingStatus xmlns="Calendar:">0</MeetingStatus>
     </ApplicationData>
    </Change>
   </Commands>
  </Collection>
 </Collections>
</Sync>

Jan 10 12:27:05 sogod [20431]: <0x0x556dee1816c0[SOGoActiveSyncDispatcher]> EAS - response for device C9CF64644D1944D8A560D03F7C153DB8: <?xml version="1.0"?>
<!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
<Sync xmlns="AirSync:">
 <Collections>
  <Collection>
   <Class>Calendar</Class>
   <SyncKey>1736506203</SyncKey>
   <CollectionId>vevent%2Fpersonal</CollectionId>
   <Status>1</Status>
   <Responses>
    <Change>
     <ServerId>290B-677FE580-31-122BB540</ServerId>
     <Status>1</Status>
    </Change>
   </Responses>
  </Collection>
 </Collections>
</Sync>



2. Change request gets broadcasted
-----------------------------------
Jan 10 12:27:07 sogod [23757]: <0x0x556df59f0ed0[SOGoActiveSyncDispatcher]> EAS - response for device E429277DBAF04AE1A5AC0E1F9E9D8B0A: <?xml version="1.0"?>
<!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
<Sync xmlns="AirSync:">
 <Collections>
  <Collection>
   <Class>Email</Class>
   <SyncKey>42013-164408</SyncKey>
   <CollectionId>mail%2F2dff4e04c6265358eb110000a63bd99d</CollectionId>
   <Status>1</Status>
  </Collection>
  <Collection>
   <Class>Calendar</Class>
   <SyncKey>1736508425</SyncKey>
   <CollectionId>vevent%2Fpersonal</CollectionId>
   <Status>1</Status>
   <Commands>
    <Change>
     <ServerId>43D0-677FE580-25-45B4C700</ServerId>
     <ApplicationData>
      <AllDayEvent xmlns="Calendar:">0</AllDayEvent>
      <StartTime xmlns="Calendar:">20250212T110000Z</StartTime>
      <EndTime xmlns="Calendar:">20250212T130000Z</EndTime>
      <TimeZone xmlns="Calendar:">xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
      <BusyStatus xmlns="Calendar:">2</BusyStatus>
      <MeetingStatus xmlns="Calendar:">0</MeetingStatus>
      <Subject xmlns="Calendar:">Mittagessen Dagobert Duck</Subject>
      <UID xmlns="Calendar:">040000008200E00074C5B7101A82E00800000000F07EF645B062DB01000000000000000010000000AAEB3FBBDEAF2A46A6B6D5038B9032E8</UID>
      <Sensitivity xmlns="Calendar:">0</Sensitivity>
      <Categories xmlns="Calendar:">
       <Category>JP</Category>
      </Categories>
      <Reminder xmlns="Calendar:">10</Reminder>
      <NativeBodyType xmlns="AirSyncBase:">1</NativeBodyType>
     </ApplicationData>
    </Change>
   </Commands>
  </Collection>
...


3. New change request at 11:37
------------------------------
Jan 10 12:37:35 sogod [14321]: <0x0x556df42a0f80[SOGoActiveSyncDispatcher]> EAS - request for device C9CF64644D1944D8A560D03F7C153DB8: <?xml version="1.0"?>
<!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
<Sync xmlns="AirSync:">
 <Collections>
  <Collection>
   <SyncKey>1736508450</SyncKey>
   <CollectionId>vevent%2Fpersonal</CollectionId>
   <DeletesAsMoves>0</DeletesAsMoves>
   <GetChanges>0</GetChanges>
   <WindowSize>512</WindowSize>
   <Options>
    <FilterType>0</FilterType>
    <BodyPreference xmlns="AirSyncBase:">
     <Type>1</Type>
     <AllOrNone>1</AllOrNone>
    </BodyPreference>
   </Options>
   <Commands>
    <Change>
     <ServerId>290B-677FE580-31-122BB540</ServerId>
     <ApplicationData>
      <TimeZone xmlns="Calendar:">xP///00AaQB0AHQAZQBsAGUAdQByAG8AcADkAGkAcwBjAGgAZQAgAFoAZQBpAHQAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAE0AaQB0AHQAZQBsAGUAdQByAG8AcADkAGkAcwBjAGgAZQAgAFMAbwBtAG0AZQByAHoAZQBpAHQAAAAAAAAAAAAA
      <DTStamp xmlns="Calendar:">20250110T113737Z</DTStamp>
      <StartTime xmlns="Calendar:">20250212T110000Z</StartTime>
      <Subject xmlns="Calendar:">Mittagessen Dagobert Duck</Subject>
      <UID xmlns="Calendar:">040000008200E00074C5B7101A82E00800000000F07EF645B062DB01000000000000000010000000AAEB3FBBDEAF2A46A6B6D5038B9032E8</UID>
      <EndTime xmlns="Calendar:">20250212T130000Z</EndTime>
      <Categories xmlns="Calendar:">
       <Category>JP</Category>
      </Categories>
      <Sensitivity xmlns="Calendar:">0</Sensitivity>
      <BusyStatus xmlns="Calendar:">2</BusyStatus>
      <AllDayEvent xmlns="Calendar:">0</AllDayEvent>
      <Reminder xmlns="Calendar:">10</Reminder>
      <MeetingStatus xmlns="Calendar:">0</MeetingStatus>
     </ApplicationData>
    </Change>
   </Commands>
  </Collection>
 </Collections>
</Sync>
Jan 10 12:37:35 sogod [14321]: <0x0x556df42a0f80[SOGoActiveSyncDispatcher]> EAS - Change - Process change for folder personal easId 290B-677FE580-31-122BB540
Jan 10 12:37:35 sogod [14321]: <0x0x556df42a0f80[SOGoActiveSyncDispatcher]> EAS - Found serverId: 040000008200E00074C5B7101A82E00800000000E09B5642B062DB01000000000000000010000000AAEB3FBBDEAF2A46A6B6D5038B9032E8 for easId: 290B-677FE580-31
-122BB540
Jan 10 12:37:35 sogod [14321]: <0x0x556df42a0f80[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content.
Jan 10 12:37:35 sogod [14321]: <0x0x556df42a0f80[SOGoActiveSyncDispatcher]> EAS - response for device C9CF64644D1944D8A560D03F7C153DB8: <?xml version="1.0"?>
<!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/">
<Sync xmlns="AirSync:">
 <Collections>
  <Collection>
   <Class>Calendar</Class>
   <SyncKey>1736508450</SyncKey>
   <CollectionId>vevent%2Fpersonal</CollectionId>
   <Status>1</Status>
   <Responses>
    <Change>
     <ServerId>290B-677FE580-31-122BB540</ServerId>
     <Status>8</Status>
    </Change>
   </Responses>
  </Collection>
 </Collections>
</Sync>





Sourcecode leading to this
--------------------------
          // Fetch the object and apply the changes
          sogoObject = [theCollection lookupName: [serverId sanitizedServerIdWithType: theFolderType]
                                       inContext: context
                                         acquire: NO];

          // Object was removed inbetween sync/commands?
          if ([sogoObject isKindOfClass: [NSException class]])
            {
              [theBuffer appendString: @"<Change>"];
              [theBuffer appendFormat: @"<ServerId>%@</ServerId>", origServerId];
              [theBuffer appendFormat: @"<Status>%d</Status>", 8];
              [theBuffer appendString: @"</Change>"];
              continue;
            }
sogo-log-err-itemdel.txt (8,368 bytes)   

Issue History

Date Modified Username Field Change
2025-01-10 13:27 leecher New Issue
2025-01-10 13:27 leecher File Added: sogo-log-err-itemdel.txt