[horde] 500 error with activesync
Michael J Rubinsky
mrubinsk at horde.org
Sat Jun 15 21:03:55 UTC 2013
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"]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"]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
>>>
>>> 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.
--
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/20130615/844060c4/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/20130615/844060c4/attachment-0003.bin>
More information about the horde
mailing list