Changes have been made in Git (FRAMEWORK_5_2):

commit 6030abd4cc85510ad5442935153be9566f3cedbe
Author: Jan Schneider <jan@horde.org>
Date:   Fri Jun 13 14:36:03 2014 +0200

     Hide exception if requested (Bug #12160).

  kronolith/lib/Driver/Ical.php |   52 ++++++++++++++++++++++++++--------------
  1 files changed, 34 insertions(+), 18 deletions(-)

http://github.com/horde/horde/commit/6030abd4cc85510ad5442935153be9566f3cedbe

Changes have been made in Git (master):

commit 1bf7e4d1ebc003d3780a4f07a3bdca8fb0af30ce
Author: Jan Schneider <jan@horde.org>
Date:   Fri Jun 13 14:36:03 2014 +0200

     Hide exception if requested (Bug #12160).

  kronolith/lib/Driver/Ical.php |   52 ++++++++++++++++++++++++++--------------
  1 files changed, 34 insertions(+), 18 deletions(-)

http://github.com/horde/horde/commit/1bf7e4d1ebc003d3780a4f07a3bdca8fb0af30ce

Thanks.

As I mentioned earlier, I think the ical Driver is also missing 
'hide_exceptions'.
@Jan: Do you want to take a look at this since you worked on the CalDAV stuff?

Nice work :)

Changes have been made in Git (master):

commit 0e2557ed260eb075896ed8e326e8ff77e99b6e9a
Author: Thomas Jarosch <thomas.jarosch@intra2net.com>
Date:   Sun Aug 25 23:00:19 2013 +0200

     Fix _listEvents() for recurrence without fixed end date.

     If we have a recurrence without a fixed end date,
     we have to calculate the next recurrence to see
     if it's outside the requested start <-> end time period.

     Ported and adapted the fix from the Kolab driver.

     Bug 12160

     Signed-off-by: Michael J Rubinsky <mrubinsk@horde.org>

  kronolith/lib/Driver/Horde.php |   24 +++++++++++++++++-------
  kronolith/lib/Driver/Ical.php  |   23 ++++++++++++++++-------
  2 files changed, 33 insertions(+), 14 deletions(-)

http://git.horde.org/horde-git/-/commit/0e2557ed260eb075896ed8e326e8ff77e99b6e9a

Changes have been made in Git (master):

commit f9ecfbb38fbb4eef5c1abedceefb00168a624347
Author: Thomas Jarosch <thomas.jarosch@intra2net.com>
Date:   Sun Aug 25 22:44:18 2013 +0200

     Fix 'hide_exceptions' option

     Part of bug 12160

     Signed-off-by: Michael J Rubinsky <mrubinsk@horde.org>

  kronolith/lib/Driver/Kolab.php |    4 ++++
  1 files changed, 4 insertions(+), 0 deletions(-)

http://git.horde.org/horde-git/-/commit/f9ecfbb38fbb4eef5c1abedceefb00168a624347

Changes have been made in Git (master):

commit ef93707a86275bf93d7bc2ddce7573a3b5a81a0a
Author: Thomas Jarosch <thomas.jarosch@intra2net.com>
Date:   Sun Aug 25 22:38:15 2013 +0200

     Fix _listEvents() for recurrence without fixed end date.

     If we have a recurrence without a fixed end date,
     we have to calculate the next recurrence to see
     if it's outside the requested start <-> end time period.

     Bug 12160

     Signed-off-by: Michael J Rubinsky <mrubinsk@horde.org>

  kronolith/lib/Driver/Kolab.php |   23 ++++++++++++++++-------
  1 files changed, 16 insertions(+), 7 deletions(-)

http://git.horde.org/horde-git/-/commit/ef93707a86275bf93d7bc2ddce7573a3b5a81a0a

The broken recurrence expansion logic is also present in the 'Horde' 
driver and in the iCal driver.

I've fixed both and tested the 'Horde' driver with birthday events from Turba.
Please test the iCal driver before committing, I fixed it without 
running the code.

Next bug: 'hide_exceptions' is not implemented for the Kolab driver.

Though this did not trigger the endless loop as first speculated.

Attached patch fixes the issue.
IHMO the same bug is present in the iCal driver.

After several hours of debugging I finally figured out what's going on:
The code to exclude recurring objects ending in the past was not 
working correctly.

Consider this scenario:
We call _listEvents($startDate = "2012-10-20", $endDate=null). We have 
the following event:

     start: 2012-09-17 10:00
     end: 2012-09-17 12:00
     recurrence: type: daily, start: 2012-09-17, interval: 2

As there is no fixed recurrence end date, the current code failed
to examine the recurrence and passed that event on to Kronolith::addEvents().

Kronolith::addEvents() later on noticed it's a recurring event and
tried to calculate the start date of the event as "$startDate = 
$event->nextRecurrence($startDate)".
It didn't expect that nextRecurrence() might return false and then ran 
into an endless loop.

Attached patch fixes the recurrence handling.

With this patch applied, the endless loop is gone
(and my safety protection loggers don't detect anything).

The SQL driver already works correctly.

I'll dive into it (now).

I still cannot reproduce this and I cannot see any way for this code 
to be triggered. An event that has a value set for baseid MUST NEVER 
recur. It represents an exception to a recurring event. We don't 
support exceptions that recur.

And, in fact from your logs we see that we are asking for only events 
that contain a baseid value. I.e., we are asking for only exceptions 
to a recurring event:

2013-07-26T14:04:45+02:00 INFO: HORDE [kronolith] TOMJ: search query: 
stdClass Object
(
     [start] => Horde_Date Object
         (
             [_year:protected] => 2012
             [_month:protected] => 10
             [_mday:protected] => 15
             [_hour:protected] => 10
             [_min:protected] => 30
             [_sec:protected] => 0
             [_timezone:protected] => Europe/Berlin
             [_defaultFormat:protected] => Y-m-d H:i:s
             [_formatCache:protected] => Array
                 (
                 )

         )

     [end] =>
     [baseid] => 51f25de0-ae9c-4982-a516-096eac100191
)

This shows that the search query contains a baseid. In other words, 
the only events that should match this search MUST contain a baseid 
value and that value MUST be equal to the value listed above. Yet, in 
Kronolith::addEvents() your log shows that the baseid for an event 
that was found in the search call is actually empty:

2013-07-26T14:04:45+02:00 INFO: HORDE [kronolith] TOMJ: addEvents(): 
event->baseid:  recurs:  [pid 24833 on line 311 of 
"/datastore/share/pear/www/horde/kronolith/lib/Kronolith.php"]

You need to find out why Kronolith_Driver::search() is returning 
events that do not match the query being passed in.

Hi Michael,
I've traced this a bit further. Attached you'll find my updated debug 
logging patch.
The patch is against kronolith git HEAD.

I'll send you the log in a private email since it's very verbose now
and might contain sensitive information.

You can easily grep for important lines with "TOMJ:".
I've also added the specific debug output you requested
in earlier comments of this ticket.

HTH
Thomas

I'll try to dive into this again next week, I just triggered it again 
with git HEAD.

Can you see what the value of $query is Kronolith_Driver#search() and 
when the error gets triggered, what is the value of $event->baseid? 
Your dump only shows it as blank, I need to know the actual, explicit 
value.

Hmm... look at the "tomj_horde_date.log" file, it provides a complete 
dump of the event structure in case it encounters the error. Should 
include event exceptions, too. I also have a Kolab XML event that 
triggers the problem, though I doubt it's any use to you :)

When we call search though, we are supposed to be filtering on 
$event->baseid which should NEVER be set on an event that recurs, only 
on an exception to a recurring event.

Can you provide an example of an event that is causing this to break 
for you, or the steps to create such an event? I cannot reproduce this.

Here you go:

Backtrace:
  1. Horde_Rpc_ActiveSync->getResponse() 
/datastore/DEVEL/horde/horde/rpc.php:156
  2. Horde_ActiveSync->handleRequest() 
/datastore/DEVEL/horde/framework/Rpc/lib/Horde/Rpc/ActiveSync.php:141
  3. Horde_ActiveSync_Request_Base->handle() 
/datastore/DEVEL/horde/framework/ActiveSync/lib/Horde/ActiveSync.php:642
  4. Horde_ActiveSync_Request_Sync->_handle() 
/datastore/DEVEL/horde/framework/ActiveSync/lib/Horde/ActiveSync/Request/Base.php:218
  5. Horde_ActiveSync_Sync->syncronize() 
/datastore/DEVEL/horde/framework/ActiveSync/lib/Horde/ActiveSync/Request/Sync.php:794
  6. Horde_Core_ActiveSync_Driver->getMessage() 
/datastore/DEVEL/horde/framework/ActiveSync/lib/Horde/ActiveSync/Sync.php:213
  7. Horde_Core_ActiveSync_Connector->calendar_export() 
/datastore/DEVEL/horde/framework/Core/lib/Horde/Core/ActiveSync/Driver.php:676
  8. Horde_Registry_Caller->export() 
/datastore/DEVEL/horde/framework/Core/lib/Horde/Core/ActiveSync/Connector.php:96
  9. Horde_Registry_Caller->__call() 
/datastore/DEVEL/horde/framework/Core/lib/Horde/Core/ActiveSync/Connector.php:96
10. Horde_Registry->call() 
/datastore/DEVEL/horde/framework/Core/lib/Horde/Registry/Caller.php:41
11. Horde_Registry->callByPackage() 
/datastore/DEVEL/horde/framework/Core/lib/Horde/Registry.php:1043
12. call_user_func_array() 
/datastore/DEVEL/horde/framework/Core/lib/Horde/Registry.php:1086
13. Kronolith_Api->export()
14. Kronolith_Event->toASAppointment() 
/datastore/DEVEL/horde/kronolith/lib/Api.php:802
15. Kronolith_Driver->search() 
/datastore/DEVEL/horde/kronolith/lib/Event.php:1602
16. Kronolith_Driver->listEvents() 
/datastore/DEVEL/horde/kronolith/lib/Driver.php:164
17. Kronolith_Driver_Kolab->_listEvents() 
/datastore/DEVEL/horde/kronolith/lib/Driver.php:308
18. Kronolith::addEvents() 
/datastore/DEVEL/horde/kronolith/lib/Driver/Kolab.php:283
19. Horde::debug() /datastore/DEVEL/horde/kronolith/lib/Kronolith.php:456


-> kronolith/lib/Driver.php:search() does not pass any options to 
listEvents().
So $cover_date is true in this case.

Hm. Though ActiveSync also sets cover_dates to false, so that code 
should never even be hit.  Can you use Horde::debug($message); instead 
of your custom file output? This will give a backtrace as well so we 
can see what the code path was.

It's because ActiveSync sets $showRecurrence to false since the client 
calculates the event recurrences and we must only send the data once.

Debug dump of the data causing the infinity loop.


The xdebug trace (623MB) is also full of

"Horde_ErrorHandler::errorHandler($errno = 8, $errstr = 'Trying to get 
property of non-object', $errfile = 
'/datastore/DEVEL/horde/kronolith/lib/Kronolith.php'"

error messages.

Debug logging patch.

Hi,

I've traced an infinity loop with kronolith for two days now.
Neither xdebug nor xhprof were of any help since
the script never finished or timed out if PHP limits were active.

The root problem is that kronolith/lib/kronolith.php::addEvents() does not
check the return value of "$event->recurrence->nextRecurrence()" in two
places and just assumes it's a Horde_Date object afterwards.
This is wrong as nextRecurrence() might return 'false'

The problem itself also does not show with the kronolith web UI,
it's only triggered when using ActiveSync. Probably ActiveSync
sets a "funny" startDate or endDate for the addEvents() call.

Please see the attached patch how I modified the code
to output more debug information + the actual debug log.

Cheers,
Thomas