[horde] 500 error with activesync
Andreas Mauser
andreas at mauser.info
Sun Jun 16 08:32:56 UTC 2013
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.
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/76d4239e/attachment.bin>
More information about the horde
mailing list