OU Search Indexing Not Completing

[StephHay]

Hello,

I previously chatted to yourselves about the problems we were experiencing to do with the other OU plugins where certain characters and words were generating database errors when entered into posts or pages. We were told the way to fix this was to upgrade the OU search plugin which we have done on our development and test versions of Moodle. However, when we run the post install PHP script to re-index existing content it is failing to reindex all our content, seeming to stop after roughly 1 hour and 40 minutes. There is no time out set on our test system. I wondered if anyone has ever encountered this problem before?

I can send through some log files if that would be helpful, I'm trying to see if there is something obvious we have missed here. It all ran as expected on our development version of Moodle which has slightly less data than test but not much.

If you need any additional information let me know, any help or advice would be much appreciated.

Cheers,

Steph

[DrewGleeson]

Hi

For additional info on this, this looks to be the log entry for when the index rebuild process fails:

Potential coding error - active database transaction detected during request shutdown:
* line 3449 of /mod/forumng/mod_forumng.php: call to moodle_database->start_delegated_transaction()
* line 140 of /mod/forumng/lib.php: call to mod_forumng::search_update_all()
* line 41 of /local/ousearch/postinstall.php: call to forumng_ousearch_update_all()
, referer: /local/ousearch/postinstall.php

Do you know what could cause this?

Thanks in advance,
Andrew

P.S. It does look more related to "mod_forumng", but hopefully if you've seen something similar before you could help shed some light on this.

[sammarshallou]

Sorry I have been really busy here... Unfortunately I don't know what is causing this problem. The error given only indicates that the script aborted unexpectedly - all that means is that, at the point when it exited, it was in the middle of a database transaction. It doesn't help us figure out why it exited in the first place.

[DrewGleeson]

Thanks for your reply @sammarshallou

Unfortunately there is not much else in the logs before that message besides the below messages which I get when attempting to access the Moodle home page from another tab in the same browser session:
[:error] Cannot obtain session lock for sid: tmr8krfeb3p1sle8vjuk0bhsu3

[:error] Default exception handler: Timed out while waiting for session lock.
Wait for your current requests to finish and try again later. Debug: 
Error code: sessionwaiterr
* line 1668 of /lib/dml/mysqli_native_moodle_database.php: dml_sessionwait_exception thrown
* line 175 of /lib/classes/session/database.php: call to mysqli_native_moodle_database->get_session_lock()
* line ? of unknownfile: call to core\\session\\database->handler_read()\n* line 42 of /lib/classes/session/handler.php: call to session_start()
* line 77 of /lib/classes/session/manager.php: call to core\\session\\handler->start()
* line 773 of /lib/setup.php: call to core\\session\\manager::start()
* line 44 of /config.php: call to require_once()
* line 38 of /my/index.php: call to require_once()

While the index rebuild is running, I cannot see any status update although my colleague, Steph, can when she runs the index rebuild (pretty strange).
The application is also generally accessible from other browser sessions, just not the same browser.

She also gets a similar failure, but at a different point in the process to me and with additional log messages:

[:error] PHP Notice: Undefined variable: count in /u01/app/moodle/moodle/mod/oublog/lib.php on line 567, referer: /local/ousearch/postinstall.php

[:error] PHP Fatal error:  Maximum execution time of 300 seconds exceeded in /u01/app/moodle/moodle/cache/classes/loaders.php on line 542,
referer: https://www-dev.moodle.is.ed.ac.uk/local/ousearch/postinstall.php

[:error] Potential coding error - active database transaction detected during request shutdown:
* line 297 of /local/ousearch/searchlib.php: call to moodle_database->start_delegated_transaction()
* line 1909 of /mod/oublog/locallib.php: call to local_ousearch_document->update()
* line 557 of /mod/oublog/lib.php: call to oublog_search_update()
* line 41 of /local/ousearch/postinstall.php: call to oublog_ousearch_update_all()
,referer: /local/ousearch/postinstall.php

Question: Is there a clear way to tell how far the index rebuild process has gotten?
i.e. when it has actually completed successfully (besides just the lack of error messages;-)

Software versions:
Moodle: 2.8.6+ (Build: 20150528)
OUsearch: 2015050100

[sammarshallou]

Re not seeing progress, make sure you are using a normal browser i.e. not IE - historically I remember there were problems with IE not updating the page until it's completely finished, not sure if that still applies with current IE versions but it might do.

The count error sounds like a potential problem (with oublog not ousearch).

Re maximum execution time, that sounds like there was a timeout because it takes too long! Looking at the code for oublog_ousearch_update_all, for instance, I think there is no mechanism to prevent it timing out - the code needs to reset the timeout each time around its loop, but it isn't doing that. Perhaps you could raise this on the tracker for the relevant modules.

This is probably the most likely cause of the problem ie you have a lot of forum/blog/etc posts so it times out. I think this mechanism is a little bit ropey because we/most people probably haven't needed to rely on it...

(So you can estimate how long it will take - it's probably vaguely on the order of 1 second per forum post or blog post etc, something like that.)

[DrewGleeson]

Thanks Sam

I like that: "a normal browser i.e. not IE" ;-)
I was using firefox, although when you say "IE not updating the page until it's completely finished" could be the same in Firefox, but obviously the process was not actually completing successfully which does not help.
In Chrome I get more real time type results, so all good there.

As for your suggestion regarding a mechanism for the application to reset the timeout value, I believe that in this case this is actually the cause of the problem.

mod_forumng.php does attempt to implement this mechanism with the intention of allowing additional time.
This is done by calling php function set_time_limit(int $seconds) with a value of 300 within the loop as you suggest.
The default max_execution_time (if not defined in php.ini) is 30 seconds, so 300 seconds would in this case be an increase.
In our environment however, this timeout value us set at 600 seconds, so this is in fact a decrease in timeout;-(

This override of the max_execution_time seems to then persist for the rest of the process for ouwiki and oublog, which have both failed on separate occasions due to the 300 seconds timeout.

I have overcome this issue at the moment by simply changing this timeout value in mod_forumng.php to 600 seconds.

I have now actually removed it completely, allowing for the PHP config to handle things.
Waiting to see how that goes.

I will raise this point (with results found) over on forumng github issue tracker page:
moodleou/moodle-mod_forumng#62

I can't help feeling like (if required) a temporary increase in the PHP max_execution_time via php.ini makes most sense, as otherwise there becomes a need to change code if the hard coded timeout value is insufficient (as in our case).

If you are happy too, we can close this issue tracker.

Thanks for your time.

Cheers,
Andrew

[sammarshallou]

Thanks Andrew! Yes I'll close this as I think the issues should be resolved within the code for each module.

It sounds like ForumNG is using the 'old way' to increase the time limit. The correct 'new way' in Moodle (disclaimer, I added this myself about a year ago) is something like, off top of my head, core_php_time_limit::raise() which is a function that will only increase the time limit and not decrease it. Calling it repeatedly in a loop is correct, that way it 'can't' be insufficient - the raised time limit starts from where you are, so in the forumng case if it calls it for every discussion say, that means it has 300 seconds per discussion, so however manhy forums you have, even if it takes 10 hours, it won't time out.