[horde] 500 error with activesync

Andreas Mauser andreas at mauser.info
Sun Jun 16 08:48:22 UTC 2013


----- Nachricht von Andreas Mauser <andreas at mauser.info> ---------
   Datum: Sun, 16 Jun 2013 10:32:56 +0200
     Von: Andreas Mauser <andreas at mauser.info>
Betreff: Re: [horde] 500 error with activesync
      An: "Mailingliste, Horde" <horde at lists.horde.org>


> Hi Michael,
>
> ----- Nachricht von Michael J Rubinsky <mrubinsk at horde.org> ---------
>      Datum: Sat, 15 Jun 2013 17:03:55 -0400
>        Von: Michael J Rubinsky <mrubinsk at horde.org>
> Antwort an: mrubinsk at horde.org
>    Betreff: Re: [horde] 500 error with activesync
>         An: horde at lists.horde.org
>
>> Quoting Andreas Mauser <andreas at mauser.info>:
>>
>>> ----- Nachricht von Michael J Rubinsky <mrubinsk at horde.org> ---------
>>>     Datum: Sat, 15 Jun 2013 11:33:23 -0400
>>>       Von: Michael J Rubinsky <mrubinsk at horde.org>
>>> Antwort an: mrubinsk at horde.org
>>>   Betreff: Re: [horde] 500 error with activesync
>>>        An: horde at lists.horde.org
>>>
>>>> Quoting Andreas Mauser <andreas at mauser.info>:
>>>>
>>>>> Hi,
>>>>>
>>>>> I found some problems in my syslog, and hoped we had this problem
>>>>> already?
>>>>> Could not find it in the mailing list.
>>>>>
>>>>> 2013-06-15T17:00:05.372769+02:00 webster HORDE: [horde] Buffer
>>>>> contents:
>>>>>  [pid 3624 on line 160 of
>>>>> "/usr/share/pear/Horde/Rpc/ActiveSync.php"]Jun
>>>>> 15 17:00:05 webster HORDE: [horde] Buffer contents:  [pid 3624 on
>>>>> line 160
>>>>> of
>>>>>
> "/usr/share/pear/Horde/Rpc/ActiveSync.php"]2013-06-15T17:00:05.393054+02:00
>>>>> webster HORDE: [horde] Returning HTTP 500 while handling Sync
>>>>> command. [pid
>>>>> 3580 on line 156 of
>>>>> "/var/www/html/mauser.info/mailoffice/rpc.php[1]"]Jun 15
>>>>> 17:00:05 webster HORDE: [horde] Returning HTTP 500 while handling Sync
>>>>> command. [pid 3580 on line 156 of
>>>>>
> "/var/www/html/mauser.info/mailoffice/rpc.php[1]"]2013-06-15T17:00:05.393382+02:00
>>>>> webster HORDE: [horde] Error in communicating with ActiveSync server:
>>>>> Horde_Log_Handler_Stream: Unable to write to stream [pid 3580 on line
>>>>> 160
>>>>> of "/usr/share/pear/Horde/Rpc/ActiveSync.php"]Jun 15 17:00:05 webster
>>>>> HORDE: [horde] Error in communicating with ActiveSync server:
>>>>> Horde_Log_Handler_Stream: Unable to write to stream [pid 3580 on line
>>>>> 160
>>>>> of "/usr/share/pear/Horde/Rpc/ActiveSync.php"]
>>>>>
>>>>> The website https://www.testexchangeconnectivity.com returns:
>>>>>
>>>>> Fehler beim Testen des Befehls „FolderSync“. Weitere Details Die
>>>>> Antwort „HTTP 403 Verboten“ wurde empfangen. Die Antwort scheint
> von
>>>>> Unknown zu stammen. Antworttext: <!DOCTYPE HTML PUBLIC "-//IETF//DTD
>>>>> HTML
>>>>> 2.0//EN"> <html><head> <title>403 Forbidden</title> </head><body>
>>>>> <h1>Forbidden</h1> <p>You don't have permission to access
>>>>> /mailoffice/rpc.php on this server.</p> </body></html> 
>>>>>
>>>>> But the file is accessible and has rights:
>>>>>
>>>>> -rwxrwxrwx. 1 apache apache 5,7K  5. Jun 05:43
>>>>> /var/www/html/mauser.info/mailoffice/rpc.php[1]
>>>>>
>>>>> And I can login to Horde and use it properly.
>>>>>
>>>>> I believe it happened after an upgrade of the system or pear, I cant
>>>>> tell
>>>>> right now.
>>>>>
>>>>> Any idea about that?
>>>>
>>>> Nope. In order to have received the 500, you *must* have had access to
>>>> rpc.php. No idea what is going on with the connectivity tester. The
>>>> 500, itself, just means there was some general error in processing the
>>>> request (depending on the version of EAS a 500 is returned or a
>>>> certain wbxml status code). The actual synclog should have more
>>>> information as to what actually happened. Receiving this occasionally
>>>> is not an issue. If you receive these constantly and/or sync is not
>>>> working then something is obviously wrong.
>>>
>>> And this is the synclog...
>>> Seems after the last synched entry is an error?
>>>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Body>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         Pan y Tango
>>> Milonga in der Brotfabrik
>>>
>>> Jeden ersten Freitag im Monat
>>> ab 21:30 - 4:00 Uhr
>>> DJ: Karin Betz
>>> Eintritt: 6,-€
>>>
>>> Brotfabrik / Frankfurt am Main
>>> Bachmannstr. 2-4
>>> U-Bahn U6/U7 in Richtung Heerstraße/Hausen
>>> Haltestelle: Industriehof
>>> Brotfabrik: 069 24790800
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:Body>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:BodyTruncated>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> </POOMCAL:BodyTruncated>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       </Data>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O      </Add>
>>> 2013-06-15T22:49:36+02:00 INFO: [15026] Updating state during change
>>> 2013-06-15T22:49:36+02:00 INFO: [15026]
>>> Horde_Core_ActiveSync_Driver::getMessage(@Calendar@,
>>> 20130615214241.Baqy0ln7p2UB8JMgMzr8Aw1 at mauser.info)
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O      <Add>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       <ServerEntryId>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> 20130615214241.Baqy0ln7p2UB8JMgMzr8Aw1 at mauser.info
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       </ServerEntryId>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       <Data>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Timezone>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>>
>  xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAAFAAIAAAAAAAAAxP///w==
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Timezone>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:DtStamp>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         20130615T204936Z
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:DtStamp>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:StartTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         20130614T220000Z
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:StartTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Subject>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         test2
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:Subject>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:UID>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>>
>  32303133303631353231343234312E42617179306C6E3770325542384A4D674D7A7238417731406D61757365722E696E666F
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:UID>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Location>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         erfer
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Location>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:EndTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         20130615T220000Z
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:EndTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:Sensitivity>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Sensitivity>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:BusyStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         2
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:BusyStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:AllDayEvent>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         1
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:AllDayEvent>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Reminder>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         15
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Reminder>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:MeetingStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> </POOMCAL:MeetingStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Body>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         sdfdgsdgd
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:Body>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:BodyTruncated>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> </POOMCAL:BodyTruncated>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       </Data>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O      </Add>
>>> 2013-06-15T22:49:36+02:00 INFO: [15026] Updating state during change
>>> 2013-06-15T22:49:36+02:00 INFO: [15026]
>>> Horde_Core_ActiveSync_Driver::getMessage(@Calendar@,
>>> 20130615220251.SxsF5W1hrwcY-tqmmrnIDw7 at mauser.info)
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O      <Add>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       <ServerEntryId>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> 20130615220251.SxsF5W1hrwcY-tqmmrnIDw7 at mauser.info
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       </ServerEntryId>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       <Data>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Timezone>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>>
>  xP///wAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAoAAAAFAAMAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAAFAAIAAAAAAAAAxP///w==
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Timezone>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:DtStamp>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         20130615T204936Z
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:DtStamp>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:StartTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         20130615T220000Z
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:StartTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Subject>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         huga
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:Subject>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:UID>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>>
>  32303133303631353232303235312E5378734635573168727763592D74716D6D726E49447737406D61757365722E696E666F
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:UID>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:EndTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         20130615T230000Z
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        </POOMCAL:EndTime>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:Sensitivity>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Sensitivity>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:BusyStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         2
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:BusyStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O        <POOMCAL:Reminder>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         15
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> </POOMCAL:Reminder>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:MeetingStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> </POOMCAL:MeetingStatus>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
> <POOMCAL:BodyTruncated>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O         0
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       
>>> </POOMCAL:BodyTruncated>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O       </Data>
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O      </Add>
>>> 2013-06-15T22:49:36+02:00 INFO: [15026] Updating state during change
>>> 2013-06-15T22:49:36+02:00 INFO: [15026] Exported maxItems of messages
>>> (4) - more available.
>>> 2013-06-15T22:49:36+02:00 DEBUG: [15026] O     </Commands>
>>> 2013-06-15T22:49:36+02:00 INFO: [15026] Saving state: Array
>>> (
>>>    [0] => {51bcd09f-5710-45ef-861b-2d560a001802}7
>>>    [1] => Horde_Db_Value_Binary Object
>>>        (
>>>            [_value:protected] =>
>>>
> O:34:"Horde_ActiveSync_Folder_Collection":3:{s:10:"*_status";a:0:{}s:12:"*_serverid";s:10:"@Calendar@";s:9:"*_class";s:8:"Calendar";}
>>>        )
>>>
>>>    [2] => ANDROID1368223989028
>>>    [3] => 1371329376
>>>    [4] => @Calendar@
>>>    [5] => andreas
>>>    [6] => 8
>>> )
>>>
>>> 2013-06-15T22:49:36+02:00 NOTICE: [15026] Error saving state for
>>> synckey {51bcd09f-5710-45ef-861b-2d560a001802}7: SQLSTATE[23000]:
>>> Integrity constraint violation: 1062 Duplicate entry
>>> '{51bcd09f-5710-45ef-861b-2d560a001802}7' for key 'PRIMARY' - removing
>>> previous sync state and trying again.
>>
>> This is not an error, it's a NOTICE entry, and it means that the client
>> has requested a sync using the same synckey as the last request the
>> server processed, so the server removes the state it created during the
>> last sync request and saves it again. This happens anytime the server
>> processes a request, but the device does not receive or accept the full
>> response (with the new synckey) - so it sends the next request using the
>> same synckey. We need to find out WHY the device is receiving/accepting
>> the response. The answer is likely either earlier in the synclog, horde
>> log or webserver log.
>
> According to the full log I sent to you and your suggestion to do  
> something with this one calender entry, I just deleted this one, and  
> the 'Milonga' entry, and my test entries from yesterday.
>
> Now I do not see the SQL error anymore, still the calendar is not  
> synched anymore.
>
> I will try to remove the android out of horde activesync devices  
> again and recreate the account on the smartphone.

After recteating the account on the smartphone, and re-linking the  
phone in horde, some calendar entries being synched, some not.

And I get the SQL error again.

I set the default timezone in horde to Europe/Berlin, but that did not help.

Anything I can do or send you for help?

Thank you,
Andreas
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 1832 bytes
Desc: S/MIME Signatur
URL: <http://lists.horde.org/archives/horde/attachments/20130616/a2c08cd0/attachment-0001.bin>


More information about the horde mailing list