[horde] 500 error with activesync
Michael J Rubinsky
mrubinsk at horde.org
Sun Jun 16 13:27:21 UTC 2013
Quoting Andreas Mauser <andreas at mauser.info>:
> ----- 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.
Sounds like some calendar entries are still causing issues.
> And I get the SQL error again.
This is just a side effect/symptom of the client requesting the same
thing over and over 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?
I can look at the synclog for this attempt, but otherwise you are
probably going to need to track down what it is in your event(s) that
is causing the problem since I can't reproduce - even if I enter the
same event details here locally.
--
mike
The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-keys
Size: 2200 bytes
Desc: PGP Public Key
URL: <http://lists.horde.org/archives/horde/attachments/20130616/23228fb2/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 6062 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.horde.org/archives/horde/attachments/20130616/23228fb2/attachment-0003.bin>
More information about the horde
mailing list