Sean,

I've had some test code running for nearly a month now to prove out a theory I have on why repeated events get duplicated. The code finally caught the case this morning. I think I am on to it.

The timezone fix I gave you in http://drupal.org/node/86924#comment-146325 is still important, that too was a way that events duplicated. A very common one in my experience.

The other case is much more subtle.

You may have seen this issue I submitted a while ago asking about a particular stanza of code: http://drupal.org/node/89575

In that code, when the renderer sees no more events to render it sets the last rendered date to be equal to the repeat end date. When the repeat end date is zero, that sets the last rendered date to zero which starts off rendering again from the beginning. Duplicate entries are born.

But what I didn't have a theory on when I submitted that issue was how the flow got us there in the first place. Now I think I know.

Crawlers and people who plan well into the future are the catalyst for the problem. When we get up near the end of the render window (that is, the 2000 [default] days in the render table) there is a case where the last rendered date is still within the render window, but the *next* rendering is outside of that window and just a wee bit too far into the future. My theory, now backed by logs on my site this morning, is that the recursive call to render nodes returns saying that there are no nodes to render, which then causes the last rendered date to be set back to zero.

If my logs are right, I have a handful of events that are about to start getting duplicated again.

What I've done to address the problem is write a function that estimates the next rendering date. It does this by finding the last two dates rendered in the squence, it calculates the delta between them in days, it double that number (fudge factor) and adds this onto the last rendered date. If the date that results is beyond the render window we take a different code path that does not reset the rendering, it just exits the render function without doing anything.

I've written that next-date-extimate function and put it in place, but instead of taking a new code path it just logs the fact that the condition was caught and allows the flow to continue as it always had. It catches the 'estimated next date is beyond the render range' state hundreds of times a day and has for weeks, but the actual problem of a repeat series being reset to the beginning did not happen until today. I think I've used a sledge hammer to address a problem that is far more nuanced than I give it credit, but my sledge hammer approach appears to work.

As you (Sean) know I'm running a mostly rewritten version of eventrepeat, one that does not pump out new nodes, but instead spits out little table rows with just the dates leaving the node with the details alone and as a single copy. Thus my code is not useful against eventrepeat proper, but the theory that I've tested is. I think it is another vector for creating duplicate events. I hope it is the last one. I too am tired of cleaning this up.

Comments

seanbfuller’s picture

This is great info scott, I'll try and go through it in the next day or so. This is currently pretty high on my list of things to fix, so hopefully we can get it resolved.

scott.mclewin’s picture

No problem Sean. I'm going to fix my module today to log the condition but not allow it to happen, then I'll reset all of my data and let it run another course. It may take another month to see the problem happen. I will let you know if my theory does not pan out in the end.

seanbfuller’s picture

Version: 4.7.x-1.x-dev » master
Status: Active » Needs review
StatusFileSize
new5.8 KB

Here is a patch I created from the code you sent me that adds your tests, watchdog entries and code path into eventrepeat.module. Others having the duplication problem may want to try this out to see if it helps shed any light on the issue. I can't say whether this will cause any other issue with your repeating events, so you may not want to use this on a live site. Please not that I've flipped this up to cvs since that's what this patch is based on.

scott.mclewin’s picture

I think to shed light it will need to be run on a site that is visible to crawlers. Whether it is production data or not matters less, but the fundamental trigger of the problem is looking at calendars that are out near the end of the rendering range. This can of course be done by hand, by why not turn those crawlers, both good and evil, to good use?

scott.mclewin’s picture

Sean,

I think the patch is missing an important piece of the logic.

In my variant of eventrepeat I have a single node off which multiple event_projected_node row entries exist, all keyed back by the nid. In event repeat each repeat is a discrete node with its own nid and the repeat sequence is bound together by the rid value.

Within the date estimation function the following query is intended to bring back the last two dates of a series:

$result = db_query("SELECT event_end, event_start FROM event e_p_n WHERE e_p_n.nid = %d ORDER BY e_p_n.event_end DESC LIMIT 2", $nid);

This code in the the tarball I sent you works because the series of event_projected_node (e_p_n) rows is bound by the nid. As you have tweaked it in your patch the logic will only pull back a single node - the most recent one - and the logic in the rest of the function will be skipped because two dates off which to build the estimate could not e found in the result set.

I think you need to pass in the repeat identifer (rid) instead of a nid value (the rid is available at the point of call, so this is an easy change) and then run the query to join the event_repeat and event tables where event_repeat.rid == the rid you pass in. Then you will get the most recent two estimated dates.

I've got a debug screen in the eventproject module that I sent which shows the estimated dates for each node. I recommend that you bulid something similar in eventrepeat to ensure that your date estimation logic is working. Unless I am totally missing a nuance, I don't think your patch will ever generate an estimated date and thus won't catch/identify the problem.

Scott

seanbfuller’s picture

StatusFileSize
new5.82 KB

Updated version of the patch with your suggestions. Here is the exact sql line I changed for easy reference:

	$result = db_query("SELECT e.event_end, e.event_start FROM {event} e LEFT JOIN {event_repeat_nodes} ern ON e.nid=ern.nid WHERE ern.rid = %d ORDER BY e.event_end DESC LIMIT 2", $nid);

If people who are having this issue could apply and test, it would be greatly appreciated.

seanbfuller’s picture

As soon as we can get some feedback on this patch to see if it worked, I'll commit it. As I mentioned in the other issue, as soon as we get past this hump, we should be able to move this code to 4.7.

scott.mclewin’s picture

Sean,

I'm still not convinced that the patch reflects the logic it needs to. The estimation function needs to take in a repeat id, not a node id.

I think that

$est_next_date = _eventproject_estimated_next_date($repeatpattern['nid'], ...

should use 'rid' as follows:

$est_next_date = _eventproject_estimated_next_date($repeatpattern['rid'], ...

And I'd change the name of that first parameter to be $rid in the call signature and the SQL within _eventproject_estimated_next_date() to be consistent.

Perhaps I'm missing something. If you tested the estimated next date function and got the results you were expecting with the patch then go ahead and ignore this.

I've continued testing out my theory and I'm pretty confident that this particular way to cause duplicated repeat events is addressed by the change.

Scott

seanbfuller’s picture

StatusFileSize
new5.83 KB

Ah sorry about that. Unfortunately, I'm working somewhat in the dark on this one. This version should get all the points you mentioned above. Let me know if you see anything.

seanbfuller’s picture

Status: Needs review » Needs work

Scott pointed out that this still is missing a few points. I'll take another pass when I get a chance today.

seanbfuller’s picture

Title: Why repeating events get duplicated - my theory » event duplication - wrapping up the issue
Status: Needs work » Needs review
StatusFileSize
new7.8 KB

Updated version for review. I changed the logic to use eventrepeat's eventrepeat_render_nodes() function with the $update = TRUE and $get_next = TRUE flags. This more accurately returns the next date to be rendered.

I've also added a new menu item under the event repeat settings that implements some of Scott's code. This debug page allows you to see all the repeating patterns in one screen, including information on how many events are currently tied to a given repeat id and the next date to be created.

Between http://drupal.org/node/86924 and this, we will hopefully be finished with the event duplication issue. If it does come up again, the debug page will help us track down the culprit.

Let me know if you see anything out of place.

scott.mclewin’s picture

Sean - In reading the patch I cannot help but think that the 'next date' function is going to have the very problem that is causing the repeats to happen. When the 'next date' is beyond the render period, it is going to return 0, which has a dual meaning. The original intended meaning by hunmonk was that the repeat sequence was to be closed. The accidental secondary meaning was that the repeat sequence just ran out of future dates in the 2000[default] day range the module uses. The calling function cannot distinguish between these two meanings

I know from the start that I used a sledgehammer for a carpet-tack sized problem, and perhaps you've gone one level deeper in understanding this than I have. The motivation behind estimating the next date based on prior data was because the problem was happening out at the leading edge of the calendar map data.

I don't think in the patch that this line
if($est_next_date > $render_support_end) {
will ever return true. Will it?

I too hope this wraps things up. I've not seen repeats in my eventrepeat variant for several weeks after applying similar logic. I do think this approach addresses this rather nasty duplicating problem.

Scott

seanbfuller’s picture

Status: Needs review » Needs work

Well, I may have misunderstood exactly what you were trying to do with your watchdog messages. Your estimation routine didn't seem exact as the render_nodes function, but it sounds like that was by design. I took another look and I'm wondering if that actual check can be removed in the final code, because this is the important part:


        if (!$dates_to_render) {
          db_query("UPDATE {event_repeat} SET repeat_last_rendered = %d WHERE rid = %d", $repeatpattern['repeat_end'], $repeatpattern['rid']);
        } 
        else {
			// Set both the last rendered and the repeat end time to now, essentially closing out this repeat sequence.
			$end_time = time();
			db_query("UPDATE {event_repeat} SET repeat_last_rendered = %d, repeat_end = %d WHERE rid = %d", $end_time, $end_time, $repeatpattern['rid']);
        }

The big point there being that you are closing the last rendered column by setting it to now, just in case it had been set to 0 above, which may have been the whole issue.

Let me know if that sounds correct and I'll write up another patch. Sorry for the back and forth on this, but please remember that I'm trying to deal with several version of code to fix a problem that I can't seem to duplicate. You feedback is appreciated. :)

scott.mclewin’s picture

sean,

No problem on the back and forth. If I were following the 'right' process I'd be using the stock module and sending you the explicit patch. I appreciate that you are willing to work with me even though I'm on a heavily modified code base.

The estimation function is far less exact than the rendered dates. It is taking a wild guess at the next repeat date based on the existing data. This is an attempt to catch the case where date generation runs off the end of the rendered dates table and errantly returned "no more dates to render". That condition prompts the code to restart the repeat (by setting last_rendered equal to end_date, which is frequently 0). That code was assuming that repeats would only end when they ran past the end_date and did not expect end_date to be 0. I believe the fundamental problem is that there is no data in the render table for the dates the code is attempting to render, and that's how events end up being reset to the beginning and create a series of duplicated events.

The snippet you quoted replaced the "set the last rendered date to the end_date (0)" with a stop-gap "set the last rendered date to now just to prevent another !@$!@$ batch of duplicated repeat events". That was for testing to allow the problem to happen without giving me a big mess to clean up. I'm sorry that was in the version I sent you - it is confusing. In my production version now it is back to setting that to end_date. With the estimation function preventing the code flow where the next date came back as "none" because we were at the end of the render range, I don't end up setting last_rendered to end_date(0) in the wrong places now, which is good.

You may have a cleaner fix that my date estimation route - I started this off noting that I was using a sledgehammer on a very nuanced problem. The main downside to the estimation function is that it may prevent events from being created right up near the end of the render range for which there actually is data. There is also a risk of it not estimating a date that is out far enough. For example, if somebody does a repeat that is configured for the second Tuesday of the month for January and February only (but every year), the estimator may not work out that there is a ten month gap that ie needs to leap over. Hence the fudge factor multiple in there - to better cover odd cases like this.

Scott

seanbfuller’s picture

Version: master » 4.7.x-2.x-dev
seanbfuller’s picture

Status: Needs work » Needs review
StatusFileSize
new5.96 KB

After looking at this a bit more and re-reading through our comments now that I have some time, I'm thinking that all that needs to happen is for us to make sure we don't set repeat_last_rendered to 0. To recap, the issue was that sometimes $repeatpattern['repeat_end'] was 0 when we got down to the the bottom of _eventrepeat_render_nodes. For this patch, I've simplified things:

      // If there are no dates to render, set the last rendered date to the
      // end date, but only do this if the end date is not 0. If it is 0,
      // then the update line above will have already set the end date to the
      // date we ended on. This will keep us from starting over on repeat patterns
      // that don't have repeat expiration dates.
      if (!$dates_to_render && $repeatpattern['repeat_end'] != 0) {
        db_query("UPDATE {event_repeat} SET repeat_last_rendered = %d WHERE rid = %d", $repeatpattern['repeat_end'], $repeatpattern['rid']);
      }

This is how it was, only I've added the $repeatpattern['repeat_end'] != 0

So here is how the last three stanzas of code at the bottom of _eventrepeat_render_nodes work, reiterated to make sure that I know what I'm doing:

After the loop is finished going through all new nodes that need to be rendered, update the repeat_last_rendered column in the database to be the same as the date we last rendered. If we didn't do any rendering, this will remain what it was when we got it out of the database near the top of the function.

Next check the database to see if any more events will ever be rendered, by calling _eventrepeat_render_nodes as an update request without an end date.

If the answer is no, close the repeat pattern by setting the repeat_last_rendered in the database to the repeat end date. The problem is that if we had no expiration date (end date = 0) and we were out near the end of the support period, _eventrepeat_render_nodes could sometimes respond saying that there were no more events to render, but setting the end date to 0 would start everything over and we'd have dupes.

If all of the above is true, just skipping the last update if we don't have an end date should take care of everything. This seems pretty solid, but if I've got anything wrong, please let me know.

Note that I've also keep the new debug menu path that lets you see all of your repeat patterns at a glance, as it still seems like a very useful thing to have.

scott.mclewin’s picture

Sean,

Do you think this will work properly with events that do not have an end date, but instead have an end count? This is a condition where the sequence should be closed, but the end date will be 0.

I'm not so certain that this is a terrible thing - worst case there is a set of events that are no longer going to produce new repeated nodes, but are still 'open'.

When taking 'end after N event' repeats into account, this logic looks to be more sound than my date estimator. I've learned more about how the guts of eventrepeat were intended to work since crafting that solution.

Scott

Scott

francisu’s picture

StatusFileSize
new6.6 KB

I looked at this and walked through the code a few times with the debugger. I add two very small things to the patch that clarified the code, one is to remove the confusion resetting of $update, and the other to simplify the check for the repeat_COUNT_remaining.

As I understand the logic, if there are more events to be created, because they happen after the $endDate, then the recursive invocation of _eventrepeat_render_nodes will return some number of dates, which will result in nothing further being done.

However, if no nodes are returned, then we update the repeat_last_rendered to be the repeat_end. Since the repeat_last_rendered was updated based on when the last event was created, it would seem this should be the same as the repeat_end. The only thing that I can think of is that the timestamps are not exactly the same, that one of them uses the "last second of the day", and the other is the start time of the last event.

This change seems OK.

seanbfuller’s picture

Status: Needs review » Fixed

Committed to both 4.7.x-2.x and HEAD.

Anonymous’s picture

Status: Fixed » Closed (fixed)