Moodle
  1. Moodle
  2. MDL-26580

Upgrading a 1.9.10+ site to 2.0.2+ site fails with a "Maximum execution time of 300 seconds exceeded error"

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 2.0.2
    • Fix Version/s: None
    • Component/s: Installation
    • Labels:
    • Environment:
    • Database:
      Microsoft SQL
    • Affected Branches:
      MOODLE_20_STABLE
    • Rank (Obsolete):
      16406

      Description

      I'm running into a timeout problem when I upgrade a Moodle 1.9.10+ site to Moodle 2.0.2+ (Build: 20110221). The site is running under IIS 6 on Windows Server 2003 and MSSQL 2005. I started the Moodle upgrade and everything seemed to go ok. Then after about 25 minutes the Moodle upgrade screen displayed a message saying "Migrated course files" and "Migrated user icons". Each showed 100% as the result. Then the upgrade seemed to halt with no other messages.

      After about an hour I looked in the PHP Error log file (I've configured php.ini to write all errors to a log file: error_log = "C:\PHP\PHPErrors.log") and I saw the following error:

      [23-Feb-2011 07:50:11] PHP Fatal error: Maximum execution time of 300 seconds exceeded in D:\Moodle\lib\dml\sqlsrv_native_moodle_database.php on line 356

      Some research indicated that this is a PHP timeout problem so I increased the following PHP configuration settings to very high values:
      max_execution_time = 1800
      max_input_time = 1800
      session.gc_maxlifetime = 1800

      I also increased the following FastCGI configuration settings to very high values:

      ActivityTimeout=1800
      RequestTimeout=1800
      IdleTimeout=1800

      Then I edited the IIS metabase and increased the IIS CGITimeout value to a high value: CGITimeout="1800"

      After restarting the web server and restoring my 1.9.10 site I tried to run the Moodle 2.0.2+ upgrade again. Once again I got the "Maximum execution time of 300 seconds exceeded in D:\Moodle\lib\dml\sqlsrv_native_moodle_database.php on line 356" error.

      Despite making all the above PHP and IIS configuration changes the upgrade still crashing after 300 seconds. All the googling that I was able to do indicated that this timeout can be adjusted by increasing the PHP max_execution_time and max_input_time values, but this obviously hasn't worked for me.

      Line 356 in \lib\dml\sqlsrv_native_moodle_database.php contains the do_query() function with:

      $result = sqlsrv_query($this->sqlsrv, $sql);

      So, it looks like sqlsrv_query() is taking too long to complete and IIS (or PHP??) is timing out after 300 seconds instead of obeying the new ActivityTimeout and RequestTimeout PHP values that I've set.

      Is there someway that I can alter the do_query() function so that it can "ping" the web server to let it know that the script is still running and thus prevent the timeout?

        Issue Links

          Activity

          Hide
          Luis de Vasconcelos added a comment -

          The output of PHPInfo() shows the following values:

          max_execution_time : 1800
          max_input_time : 1800

          so the correct php.ini file is being loaded. And I'm quite sure that there is only one php.ini file on the web server.

          Show
          Luis de Vasconcelos added a comment - The output of PHPInfo() shows the following values: max_execution_time : 1800 max_input_time : 1800 so the correct php.ini file is being loaded. And I'm quite sure that there is only one php.ini file on the web server.
          Hide
          Luis de Vasconcelos added a comment -

          Will putting something like a flush(); somewhere in that do_query() function help?

          Show
          Luis de Vasconcelos added a comment - Will putting something like a flush(); somewhere in that do_query() function help?
          Hide
          Luis de Vasconcelos added a comment -

          From the information that Stephen Lambert posted in http://moodle.org/mod/forum/discuss.php?d=170310 it seems that the Moodle database gets corrupted if the Moodle 1.9 to 2.0 upgrade does not complete fully the first time that it is run - in other words, if you get the "Maximum execution time of 300 seconds" problem like the one I reported above and you have to restart the upgrade you are then left with a whole lot of broken links to resource files, i.e. the "This legacy resource type (file) was not yet migrated" messages.

          I have been wondering why I'm getting all those "This legacy resource type (file) was not yet migrated" messages in my courses and now it seems that these "Maximum execution time of 300 seconds" timeouts are the cause of the database corruption!

          So, how do we fix this?

          Show
          Luis de Vasconcelos added a comment - From the information that Stephen Lambert posted in http://moodle.org/mod/forum/discuss.php?d=170310 it seems that the Moodle database gets corrupted if the Moodle 1.9 to 2.0 upgrade does not complete fully the first time that it is run - in other words, if you get the "Maximum execution time of 300 seconds" problem like the one I reported above and you have to restart the upgrade you are then left with a whole lot of broken links to resource files, i.e. the "This legacy resource type (file) was not yet migrated" messages. I have been wondering why I'm getting all those "This legacy resource type (file) was not yet migrated" messages in my courses and now it seems that these "Maximum execution time of 300 seconds" timeouts are the cause of the database corruption! So, how do we fix this?
          Hide
          Martin Dougiamas added a comment -

          1) Is there a problem here to fix in code or is it the environment?
          2) Can upgrade be any more tolerant of failure?

          Show
          Martin Dougiamas added a comment - 1) Is there a problem here to fix in code or is it the environment? 2) Can upgrade be any more tolerant of failure?
          Hide
          Luis de Vasconcelos added a comment -

          Martin, the way I see it is that if the Moodle upgrade fails for any reason, such as the timeout error I reported, and it results in database corruption like the "This legacy resource type (file) was not yet migrated" problem that I also mentioned then perhaps it is something that needs to be fixed in the code.

          It's a known fact that, depending on the amount of content on the site and database, a Moodle upgrade can take a long time so it needs to ensure that the connection with the web server is maintained while those long database conversion scripts are busy doing their thing.

          If an upgrade can't be "more tolerant of failure" then how are we supposed to upgrade?

          I will continue to try and 'fix' my environment to see if I can get past this.

          Show
          Luis de Vasconcelos added a comment - Martin, the way I see it is that if the Moodle upgrade fails for any reason, such as the timeout error I reported, and it results in database corruption like the "This legacy resource type (file) was not yet migrated" problem that I also mentioned then perhaps it is something that needs to be fixed in the code. It's a known fact that, depending on the amount of content on the site and database, a Moodle upgrade can take a long time so it needs to ensure that the connection with the web server is maintained while those long database conversion scripts are busy doing their thing. If an upgrade can't be "more tolerant of failure" then how are we supposed to upgrade? I will continue to try and 'fix' my environment to see if I can get past this.
          Hide
          Mauno Korpelainen added a comment -

          Luis,

          IIS has a CGI timeout function which defaults to 300 seconds. Have you tried to set it to bigger value?

          http://www.iisadmin.co.uk/?p=7

          Show
          Mauno Korpelainen added a comment - Luis, IIS has a CGI timeout function which defaults to 300 seconds. Have you tried to set it to bigger value? http://www.iisadmin.co.uk/?p=7
          Show
          Mauno Korpelainen added a comment - + http://www.iisadmin.co.uk/?p=7&page=2 + http://www.iisadmin.co.uk/?p=7&page=3
          Hide
          Luis de Vasconcelos added a comment -

          Mauno,

          Thanks for that and yes, I did increase the CGITimeout value in the IIS 6 metabase to 7200 (2 hours).

          I also set the ActivityTimeout, RequestTimeout and IdleTimeout settings in the FastCGI config file to very high values. And I've played around with various values for the max_execution_time and max_input_time fields in php.ini, including max_execution_time = 0 and max_input_time = 0

          None have given me the result that I want: an uninterrupted upgrade to Moodle 2.0.2.

          On several occasions I have restarted the Moodle upgrade after encountering the maximum execution time problem and it seems to resume from where it crashed, but then I'm left with a corrupt database, i.e. most of the links to resources in my courses are broken and replaced with the "This legacy resource type (file) was not yet migrated" messages.

          The "Maximum execution time" problem seems to occur around about the time when the Moodle upgrade script shows the "Migrated course files - course 151/151 and Migrated user icons 97/97" feedback message.

          Thanks for the IIS Admin Blog link - I have already gone through that one...

          Show
          Luis de Vasconcelos added a comment - Mauno, Thanks for that and yes, I did increase the CGITimeout value in the IIS 6 metabase to 7200 (2 hours). I also set the ActivityTimeout, RequestTimeout and IdleTimeout settings in the FastCGI config file to very high values. And I've played around with various values for the max_execution_time and max_input_time fields in php.ini, including max_execution_time = 0 and max_input_time = 0 None have given me the result that I want: an uninterrupted upgrade to Moodle 2.0.2. On several occasions I have restarted the Moodle upgrade after encountering the maximum execution time problem and it seems to resume from where it crashed, but then I'm left with a corrupt database, i.e. most of the links to resources in my courses are broken and replaced with the "This legacy resource type (file) was not yet migrated" messages. The "Maximum execution time" problem seems to occur around about the time when the Moodle upgrade script shows the "Migrated course files - course 151/151 and Migrated user icons 97/97" feedback message. Thanks for the IIS Admin Blog link - I have already gone through that one...
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Hi Luis,

          just two ideas that could help detect this better:

          1) Your timeout always happen in the sqlsrv->do_query() line. This can be caused because a real problem in the driver/DB or, also be simply something caused because 99% of the time in upgrade is spent doing DB operations. So, instead of getting "simple" error lines in your web server logs it would be really interesting to get complete stack traces. That would allow to check if the "caller" where the process ends is always the same or no. To do so, I think that you need to install the xdebug extension and with it, you will get complete traces instead of simple errors. If we get the exact point of problem, we can perform some checks in your DB to see if something is wrong of we should give more time to some upgrade step. That's the correct way to go.

          2) The second idea is one quick hack to see if that causes any modification in your upgrade. Just edit lib/moodlelib.php, look for "function upgrade_set_timeout" and make this change (2 lines to add):

           function upgrade_set_timeout($max_execution_time=300) {
               global $CFG;
           
          +    $max_execution_time = (!empty($max_execution_time) && $max_execution_time < 3600) ? 3600 : $max_execution_time;
          +
               if (!isset($CFG->upgraderunning) or $CFG->upgraderunning < time()) {
                   $upgraderunning = get_config(null, 'upgraderunning');
               } else {
          

          That will cause any timeout < 3600 (like the 300 one you are getting) to be increased to 3600 (1 hour). Then run the upgrade again and let's see what happens. If by giving 1hour you are able to complete it, then we need to detect the exact point of failure, as commented at 1) above, because we should increase it for sure to avoid problems.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Hi Luis, just two ideas that could help detect this better: 1) Your timeout always happen in the sqlsrv->do_query() line. This can be caused because a real problem in the driver/DB or, also be simply something caused because 99% of the time in upgrade is spent doing DB operations. So, instead of getting "simple" error lines in your web server logs it would be really interesting to get complete stack traces. That would allow to check if the "caller" where the process ends is always the same or no. To do so, I think that you need to install the xdebug extension and with it, you will get complete traces instead of simple errors. If we get the exact point of problem, we can perform some checks in your DB to see if something is wrong of we should give more time to some upgrade step. That's the correct way to go. 2) The second idea is one quick hack to see if that causes any modification in your upgrade. Just edit lib/moodlelib.php, look for "function upgrade_set_timeout" and make this change (2 lines to add): function upgrade_set_timeout($max_execution_time=300) { global $CFG; + $max_execution_time = (!empty($max_execution_time) && $max_execution_time < 3600) ? 3600 : $max_execution_time; + if (!isset($CFG->upgraderunning) or $CFG->upgraderunning < time()) { $upgraderunning = get_config( null , 'upgraderunning'); } else { That will cause any timeout < 3600 (like the 300 one you are getting) to be increased to 3600 (1 hour). Then run the upgrade again and let's see what happens. If by giving 1hour you are able to complete it, then we need to detect the exact point of failure, as commented at 1) above, because we should increase it for sure to avoid problems. Ciao
          Hide
          Luis de Vasconcelos added a comment -

          Thanks. I'll try the upgrade again and then I'll provide some feedback.

          Show
          Luis de Vasconcelos added a comment - Thanks. I'll try the upgrade again and then I'll provide some feedback.
          Hide
          Luis de Vasconcelos added a comment -

          Thanks. I installed XDebug and tried profiling the 1.9 to 2 upgrade. XDebug created a 2.96 gigabyte output file! Is there an optimal way to configure XDebug for this kind of testing?

          My currrent setup:

          [XDebug]
          zend_extension="D:\PHP\ext\php_xdebug-2.1.0-5.3-vc9-nts.dll"
          xdebug.remote_enable=true
          xdebug.remote_port="9000"
          xdebug.profiler_enable=1
          xdebug.profiler_output_dir="D:\PHP\XDebug"
          xdebug.profiler_append=1
          xdebug.profiler_output_name = "xdebug.%t%R.txt"

          Show
          Luis de Vasconcelos added a comment - Thanks. I installed XDebug and tried profiling the 1.9 to 2 upgrade. XDebug created a 2.96 gigabyte output file! Is there an optimal way to configure XDebug for this kind of testing? My currrent setup: [XDebug] zend_extension="D:\PHP\ext\php_xdebug-2.1.0-5.3-vc9-nts.dll" xdebug.remote_enable=true xdebug.remote_port="9000" xdebug.profiler_enable=1 xdebug.profiler_output_dir="D:\PHP\XDebug" xdebug.profiler_append=1 xdebug.profiler_output_name = "xdebug.%t%R.txt"
          Hide
          Luis de Vasconcelos added a comment -

          I enabled XDebug and applied the above patch to function upgrade_set_timeout. Then I started the upgrade from 1.9 to 2.0 again. It ran for 5 hours before I stopped it! But perhaps that was a bad XDebug config getting in the way.

          While I was waiting the following did occur to me:

          What if I change the value of the $max_execution_time parameter that is passed to upgrade_set_timeout() to something higher:

          -function upgrade_set_timeout($max_execution_time=300) {
          +function upgrade_set_timeout($max_execution_time=3600) {

          Will this cause any problems? I'm going to try it in the morning to see what happens!

          In the meantime, I decided to try the 1.9.10+ to 2.0.2+ upgrade via the CLI (admin\cli\upgrade.php). It ran for 58 minutes and completed successfully without any errors or crashes - even though several pages in MoodleDocs say that the CLI upgrade isn't supported on Windows!

          Show
          Luis de Vasconcelos added a comment - I enabled XDebug and applied the above patch to function upgrade_set_timeout. Then I started the upgrade from 1.9 to 2.0 again. It ran for 5 hours before I stopped it! But perhaps that was a bad XDebug config getting in the way. While I was waiting the following did occur to me: What if I change the value of the $max_execution_time parameter that is passed to upgrade_set_timeout() to something higher: -function upgrade_set_timeout($max_execution_time=300) { +function upgrade_set_timeout($max_execution_time=3600) { Will this cause any problems? I'm going to try it in the morning to see what happens! In the meantime, I decided to try the 1.9.10+ to 2.0.2+ upgrade via the CLI (admin\cli\upgrade.php). It ran for 58 minutes and completed successfully without any errors or crashes - even though several pages in MoodleDocs say that the CLI upgrade isn't supported on Windows!
          Hide
          Fred Weiss added a comment -

          I have a similar problem.

          I am trying to upgrade from Moodle 1.9.11 to Moodle 2.0.2
          Running

          Windows 2008 R2, SQL 2008, IIS 7.5 , PHP 5.3.5

          We have a 8gb Moodle database, 1311 courses to convert, 68gb in moodledata in 99,545 files;

          I have done a test upgrade converting a smaller amount of data successfully but when I try to convert the entire moodledata directory it timesout.

          When I tied to do all data the upgrade failed with error below.

          Error:
          Upgrading to new version You are not logged in. (Login)System
          Increasing size of user idnumber field, this may take a while...
          Migrated course files - course 430/1311.
          3129.01 sec

          32.8% complete

          Fatal error: Maximum execution time of 300 seconds exceeded in S:\inetpub\wwwroot\moodle\lib\filestorage\file_storage.php on line 1021

          Everytime this happens it requires deleting and restoring the database and restoring the moodledata directory which is at least an 8hr process. As the upgrade converts the files it actually deletes them from moodledata and puts the upgraded version to filedir. If it could leave the files in moodledata at least you would have a easier rollback if the upgrade fails for sites with large data directories. I guess a HD space check would be required for this to happen.

          I have reset the values below to 3600, still failed, 7200 still failed and finally up to 14400. the values below seemed to get over the file conversion part. Although the upgrade then failed on the Alter Table Backuptype see http://moodle.org/mod/forum/discuss.php?d=165479 . Will add this to another tracker ticket.

          After I am able to restore eveything yet again I will try and see if I get right through the full upgrade.

          Settings

          PHP.INI

          max_execution_time : 14400
          max_input_time : 14400
          session.gc_maxlifetime 14400
          memory_limit = 2048M

          FASTCGI

          ActivityTimeout=14400
          RequestTimeout=14400

          CGI
          TIMEOUT - 6:15.00

          file_storage.php
          $timeout = isset($options['timeout']) ? $options['timeout'] : 14400; (changed from 300)

          /lib/moodlelib.php
          function upgrade_set_timeout($max_execution_time=14400) {
          global $CFG;

          + $max_execution_time = (!empty($max_execution_time) && $max_execution_time < 14400) ? 14400 : $max_execution_time;
          +
          if (!isset($CFG->upgraderunning) or $CFG->upgraderunning < time())

          { $upgraderunning = get_config(null, 'upgraderunning'); }

          else {

          Show
          Fred Weiss added a comment - I have a similar problem. I am trying to upgrade from Moodle 1.9.11 to Moodle 2.0.2 Running Windows 2008 R2, SQL 2008, IIS 7.5 , PHP 5.3.5 We have a 8gb Moodle database, 1311 courses to convert, 68gb in moodledata in 99,545 files; I have done a test upgrade converting a smaller amount of data successfully but when I try to convert the entire moodledata directory it timesout. When I tied to do all data the upgrade failed with error below. Error: Upgrading to new version You are not logged in. (Login)System Increasing size of user idnumber field, this may take a while... Migrated course files - course 430/1311. 3129.01 sec 32.8% complete Fatal error: Maximum execution time of 300 seconds exceeded in S:\inetpub\wwwroot\moodle\lib\filestorage\file_storage.php on line 1021 Everytime this happens it requires deleting and restoring the database and restoring the moodledata directory which is at least an 8hr process. As the upgrade converts the files it actually deletes them from moodledata and puts the upgraded version to filedir. If it could leave the files in moodledata at least you would have a easier rollback if the upgrade fails for sites with large data directories. I guess a HD space check would be required for this to happen. I have reset the values below to 3600, still failed, 7200 still failed and finally up to 14400. the values below seemed to get over the file conversion part. Although the upgrade then failed on the Alter Table Backuptype see http://moodle.org/mod/forum/discuss.php?d=165479 . Will add this to another tracker ticket. After I am able to restore eveything yet again I will try and see if I get right through the full upgrade. Settings PHP.INI max_execution_time : 14400 max_input_time : 14400 session.gc_maxlifetime 14400 memory_limit = 2048M FASTCGI ActivityTimeout=14400 RequestTimeout=14400 CGI TIMEOUT - 6:15.00 file_storage.php $timeout = isset($options ['timeout'] ) ? $options ['timeout'] : 14400; (changed from 300) /lib/moodlelib.php function upgrade_set_timeout($max_execution_time=14400) { global $CFG; + $max_execution_time = (!empty($max_execution_time) && $max_execution_time < 14400) ? 14400 : $max_execution_time; + if (!isset($CFG->upgraderunning) or $CFG->upgraderunning < time()) { $upgraderunning = get_config(null, 'upgraderunning'); } else {
          Hide
          Luis de Vasconcelos added a comment -

          I successfully managed to upgrade a 1.9.10+ (Build: 20110112) instance of Moodle on my test box to version 2.0.2+ (Build: 20110316).

          The only code modification that I made was to increase the $max_execution_time value in /lib/moodlelib.php from 300 to 14400:

          @@ +7740,7 -7740,7 @@

          • @global object
          • @param int $max_execution_time in seconds (can not be less than 60 s)
            */
            + function upgrade_set_timeout($max_execution_time=14400) {
          • function upgrade_set_timeout($max_execution_time=300) {
            global $CFG;

          if (!isset($CFG->upgraderunning) or $CFG->upgraderunning < time()) {

          So then what is a reasonable value for $max_execution_time?

          Also, before trying the upgrade I set the following environment options:

          1. Set the ActivityTimeout, RequestTimeout and IdleTimeout settings to 10800 in the FastCGI .ini file.
          2. Set max_input_time and max_execution_time settings to 0 in the php.ini file.
          3. Set the CGITimeout value in the IIS metabase to 7200.

          But you shouldn't have to do that on a production server.

          To really be certain that it's not an "environment" issue I will restore the FastCGI, PHP and IIS metabase settings to the original values and try the upgrade again using $max_execution_time=14400. If the upgrade is successful then it will suggest that the problem is the $max_execution_time=300 value in the upgrade_set_timeout function.

          Show
          Luis de Vasconcelos added a comment - I successfully managed to upgrade a 1.9.10+ (Build: 20110112) instance of Moodle on my test box to version 2.0.2+ (Build: 20110316). The only code modification that I made was to increase the $max_execution_time value in /lib/moodlelib.php from 300 to 14400: @@ +7740,7 -7740,7 @@ @global object @param int $max_execution_time in seconds (can not be less than 60 s) */ + function upgrade_set_timeout($max_execution_time=14400) { function upgrade_set_timeout($max_execution_time=300) { global $CFG; if (!isset($CFG->upgraderunning) or $CFG->upgraderunning < time()) { So then what is a reasonable value for $max_execution_time? Also, before trying the upgrade I set the following environment options: 1. Set the ActivityTimeout, RequestTimeout and IdleTimeout settings to 10800 in the FastCGI .ini file. 2. Set max_input_time and max_execution_time settings to 0 in the php.ini file. 3. Set the CGITimeout value in the IIS metabase to 7200. But you shouldn't have to do that on a production server. To really be certain that it's not an "environment" issue I will restore the FastCGI, PHP and IIS metabase settings to the original values and try the upgrade again using $max_execution_time=14400. If the upgrade is successful then it will suggest that the problem is the $max_execution_time=300 value in the upgrade_set_timeout function.
          Hide
          Martin Dougiamas added a comment -

          Can someone please make sure that this is longer for normal upgrades.

          Show
          Martin Dougiamas added a comment - Can someone please make sure that this is longer for normal upgrades.
          Hide
          Fred Weiss added a comment -

          As mentioned, I can do an upgrade with a smaller amount of data (in moodledata directory) the problem occurs when I try to upgrade the entire db and moodledata directory.

          Show
          Fred Weiss added a comment - As mentioned, I can do an upgrade with a smaller amount of data (in moodledata directory) the problem occurs when I try to upgrade the entire db and moodledata directory.
          Hide
          Aparup Banerjee added a comment -

          should i just increase the default in upgrade_set_timeout() and file_storage.php to 14400?

          it seems to me that the delay is due to data retrieval and could possibly be further optimized if we could just debug the real issue.

          Show
          Aparup Banerjee added a comment - should i just increase the default in upgrade_set_timeout() and file_storage.php to 14400? it seems to me that the delay is due to data retrieval and could possibly be further optimized if we could just debug the real issue.
          Hide
          Aparup Banerjee added a comment - - edited

          correct me if i'm wrong but the change to file_storage.php seems to be in
          create_file_from_url() which seem to be called only in ./mod/scorm/locallib.php:159:function scorm_parse()

          it could be that there are large scorm files present. if so, we should really add a sensible(calculated based on file size?) timeout to scorm_parse().

          Show
          Aparup Banerjee added a comment - - edited correct me if i'm wrong but the change to file_storage.php seems to be in create_file_from_url() which seem to be called only in ./mod/scorm/locallib.php:159:function scorm_parse() it could be that there are large scorm files present. if so, we should really add a sensible(calculated based on file size?) timeout to scorm_parse().
          Hide
          Luis de Vasconcelos added a comment -

          Perhaps..., but I don't use any scorm in any of my courses so that's not what was causing the timeouts on my site.

          Show
          Luis de Vasconcelos added a comment - Perhaps..., but I don't use any scorm in any of my courses so that's not what was causing the timeouts on my site.
          Hide
          Aparup Banerjee added a comment -

          thanks Luis,
          yes your specific case didn't need the file_storage.php timeout value increased. I should have addressed the my comment to Fred.

          I'm still searching in the dark with the upgrade_set_timeout() issue. it would really help if you can provide some possible form of trace, even a sensible tailend of the large xdebug file could help. Actually, any form of info that can be used to trace back what was going on would be useful.

          Fred, you did need to increase the timeout in file_storage.php, do you have large scorm files?

          In any case, heres the branch i'm working on for this:
          https://github.com/nebgor/moodle/compare/mistress...MDL-26580

          Show
          Aparup Banerjee added a comment - thanks Luis, yes your specific case didn't need the file_storage.php timeout value increased. I should have addressed the my comment to Fred. I'm still searching in the dark with the upgrade_set_timeout() issue. it would really help if you can provide some possible form of trace, even a sensible tailend of the large xdebug file could help. Actually, any form of info that can be used to trace back what was going on would be useful. Fred, you did need to increase the timeout in file_storage.php, do you have large scorm files? In any case, heres the branch i'm working on for this: https://github.com/nebgor/moodle/compare/mistress...MDL-26580
          Hide
          Luis de Vasconcelos added a comment -

          I've enabled XDebug on the test server but it's producing a 3 gigabyte file, which I won't try to attach here! Does anybody have a "optimal" XDebug configuration that I can use that will produce a smaller file?

          Show
          Luis de Vasconcelos added a comment - I've enabled XDebug on the test server but it's producing a 3 gigabyte file, which I won't try to attach here! Does anybody have a "optimal" XDebug configuration that I can use that will produce a smaller file?
          Hide
          Petr Skoda added a comment -

          Just in case you did not know it, execution of all upgrade logs is logged in the "upgrade_log" table, it is also possible to print out all SQL queries (this may produce very long output though - see config-dist.php $CFG->upgradeshowsql = true;

          In this case once the execution times out you could inspect the last record in the upgrade_log or verify the sql output.

          Show
          Petr Skoda added a comment - Just in case you did not know it, execution of all upgrade logs is logged in the "upgrade_log" table, it is also possible to print out all SQL queries (this may produce very long output though - see config-dist.php $CFG->upgradeshowsql = true; In this case once the execution times out you could inspect the last record in the upgrade_log or verify the sql output.
          Hide
          Petr Skoda added a comment -

          Hmm, we could also add --no-timeouts options to the cli upgrade script, the web interface needs some timeouts though imo.

          Show
          Petr Skoda added a comment - Hmm, we could also add --no-timeouts options to the cli upgrade script, the web interface needs some timeouts though imo.
          Hide
          Aparup Banerjee added a comment -

          Luis,
          i'm not too sure about XDebug configurations but i think its difficult to try to get a detailed log as well as cut the log short by configuration (without triggers). How about attaching the last hundred lines or so?

          Show
          Aparup Banerjee added a comment - Luis, i'm not too sure about XDebug configurations but i think its difficult to try to get a detailed log as well as cut the log short by configuration (without triggers). How about attaching the last hundred lines or so?
          Hide
          Aparup Banerjee added a comment -

          created PULL-586 for the improvement to file_storage.php but this issue isn't over yet :-/

          Show
          Aparup Banerjee added a comment - created PULL-586 for the improvement to file_storage.php but this issue isn't over yet :-/
          Hide
          Basil Gohar added a comment -

          I'm confused as to why having a timeout in the web interface is preferable to having a corrupted database that would be arduous to recover from. More frequent updates during the upgrade might remove the need for the timeouts being so short, as they would at least let the user know it's continuing. Needless to say, I'm also experiencing this issue. Here is the output I get during the upgrade from XDebug:

          ( ! ) Fatal error: Maximum execution time of 300 seconds exceeded in /var/www/eschool/lms/lib/dml/mysqli_native_moodle_database.php on line 1001
          Call Stack

          1. Time Memory Function Location
            1 0.0025 873656 {main}

            ( ) ../index.php:0
            2 0.1408 26614560 upgrade_core( $version = 2011022100, $verbose = TRUE ) ../index.php:252
            3 0.2484 36497536 xmldb_main_upgrade( $oldversion = '2007101591.02' ) ../upgradelib.php:1383
            4 649.7135 47034136 mysqli_native_moodle_database->update_record( $table = 'question_answers', $dataobject = class stdClass

            { public $id = '291725'; public $question = '88267'; public $answer = '<p>by charged particles in motion.</p>'; public $answerformat = '0'; public $fraction = '1.0000000'; public $feedback = '<p>Great!!</p>\n<p>Read more about electromagnetic waves in chapter 13 section 1 which starts on page 374.</p>'; public $feedbackformat = '0'; public $qtype = 'multichoice' }

            , $bulk = ??? ) ../upgrade.php:5098
            5 649.7135 47035184 mysqli_native_moodle_database->get_columns( $table = 'question_answers', $usecache = ??? ) ../mysqli_native_moodle_database.php:1001

          Show
          Basil Gohar added a comment - I'm confused as to why having a timeout in the web interface is preferable to having a corrupted database that would be arduous to recover from. More frequent updates during the upgrade might remove the need for the timeouts being so short, as they would at least let the user know it's continuing. Needless to say, I'm also experiencing this issue. Here is the output I get during the upgrade from XDebug: ( ! ) Fatal error: Maximum execution time of 300 seconds exceeded in /var/www/eschool/lms/lib/dml/mysqli_native_moodle_database.php on line 1001 Call Stack Time Memory Function Location 1 0.0025 873656 {main} ( ) ../index.php:0 2 0.1408 26614560 upgrade_core( $version = 2011022100, $verbose = TRUE ) ../index.php:252 3 0.2484 36497536 xmldb_main_upgrade( $oldversion = '2007101591.02' ) ../upgradelib.php:1383 4 649.7135 47034136 mysqli_native_moodle_database->update_record( $table = 'question_answers', $dataobject = class stdClass { public $id = '291725'; public $question = '88267'; public $answer = '<p>by charged particles in motion.</p>'; public $answerformat = '0'; public $fraction = '1.0000000'; public $feedback = '<p>Great!!</p>\n<p>Read more about electromagnetic waves in chapter 13 section 1 which starts on page 374.</p>'; public $feedbackformat = '0'; public $qtype = 'multichoice' } , $bulk = ??? ) ../upgrade.php:5098 5 649.7135 47035184 mysqli_native_moodle_database->get_columns( $table = 'question_answers', $usecache = ??? ) ../mysqli_native_moodle_database.php:1001
          Hide
          Basil Gohar added a comment -

          Just for the record, I still get the timeout when running using the CLI upgrade mode. More XDebug goodness:

          Fatal error: Maximum execution time of 300 seconds exceeded in /var/www/eschool/lms/lib/dml/mysqli_native_moodle_database.php on line 0

          Call Stack:
          0.0005 667328 1.

          {main}

          () /var/www/eschool/lms/admin/cli/upgrade.php:0
          7.8606 30303664 2. upgrade_core($version = 2011022100, $verbose = TRUE) /var/www/eschool/lms/admin/cli/upgrade.php:106
          7.9667 37069568 3. xmldb_main_upgrade($oldversion = '2007101591.02') /var/www/eschool/lms/lib/upgradelib.php:1383
          671.1045 44834408 4. mysqli_native_moodle_database->update_record($table = 'question_answers', $dataobject = class stdClass

          { public $id = '298798'; public $question = '90203'; public $answer = '1, 1, 1'; public $answerformat = '0'; public $fraction = '1.0000000'; public $feedback = ''; public $feedbackformat = '0'; public $qtype = 'multichoice' }

          , $bulk = ???) /var/www/eschool/lms/lib/db/upgrade.php:5098

          Show
          Basil Gohar added a comment - Just for the record, I still get the timeout when running using the CLI upgrade mode. More XDebug goodness: Fatal error: Maximum execution time of 300 seconds exceeded in /var/www/eschool/lms/lib/dml/mysqli_native_moodle_database.php on line 0 Call Stack: 0.0005 667328 1. {main} () /var/www/eschool/lms/admin/cli/upgrade.php:0 7.8606 30303664 2. upgrade_core($version = 2011022100, $verbose = TRUE) /var/www/eschool/lms/admin/cli/upgrade.php:106 7.9667 37069568 3. xmldb_main_upgrade($oldversion = '2007101591.02') /var/www/eschool/lms/lib/upgradelib.php:1383 671.1045 44834408 4. mysqli_native_moodle_database->update_record($table = 'question_answers', $dataobject = class stdClass { public $id = '298798'; public $question = '90203'; public $answer = '1, 1, 1'; public $answerformat = '0'; public $fraction = '1.0000000'; public $feedback = ''; public $feedbackformat = '0'; public $qtype = 'multichoice' } , $bulk = ???) /var/www/eschool/lms/lib/db/upgrade.php:5098
          Hide
          Basil Gohar added a comment -

          I should note that I am running Fedora 14, 64-bit, and not Windows, unlike the original reporter of this bug.

          Show
          Basil Gohar added a comment - I should note that I am running Fedora 14, 64-bit, and not Windows, unlike the original reporter of this bug.
          Hide
          Petr Skoda added a comment -

          Aparup: please add some upgrade_set_timeout() calls to 2010080901 upgrade block around 5098, the comments above indicate that it runs out of time in those loops.

          Show
          Petr Skoda added a comment - Aparup: please add some upgrade_set_timeout() calls to 2010080901 upgrade block around 5098, the comments above indicate that it runs out of time in those loops.
          Hide
          Aparup Banerjee added a comment - - edited

          Thanks for the trace Basil Gohar, its really helped!
          The issue is a timeout in the php execution itself, not the web page interface.

          Petr, thats done!
          PULL-586 and PULL-587 code updated.

          Show
          Aparup Banerjee added a comment - - edited Thanks for the trace Basil Gohar, its really helped! The issue is a timeout in the php execution itself, not the web page interface. Petr, thats done! PULL-586 and PULL-587 code updated.
          Hide
          Aparup Banerjee added a comment -

          I've also added to PULL-586 and PULL-587 some precautionary timeouts to upgrade where they may possibly time out in some cases.

          Thanks all for the reports. This should be resolved now. Please reopen if it isn't for you.

          Show
          Aparup Banerjee added a comment - I've also added to PULL-586 and PULL-587 some precautionary timeouts to upgrade where they may possibly time out in some cases. Thanks all for the reports. This should be resolved now. Please reopen if it isn't for you.
          Hide
          Petr Skoda added a comment -

          reopening, see the PULL for details, in short:
          1/ there is a potential pref trouble in upgrade_set_timeout()
          2/ we do not need to set timeout in CLI mode at all because there is no browser to timeout

          Also we need a bit more help with testing, anyway thanks everybody!

          Show
          Petr Skoda added a comment - reopening, see the PULL for details, in short: 1/ there is a potential pref trouble in upgrade_set_timeout() 2/ we do not need to set timeout in CLI mode at all because there is no browser to timeout Also we need a bit more help with testing, anyway thanks everybody!
          Hide
          Aparup Banerjee added a comment -

          Hi Luis,
          Could you download and test the patch at
          HEAD > https://github.com/nebgor/moodle/tree/MDL-26580
          or
          MOODLE_20_STABLE > https://github.com/nebgor/moodle/tree/MDL-26580_m20

          then try and run the upgrade to see if the patch fixes the timeout issue?

          Show
          Aparup Banerjee added a comment - Hi Luis, Could you download and test the patch at HEAD > https://github.com/nebgor/moodle/tree/MDL-26580 or MOODLE_20_STABLE > https://github.com/nebgor/moodle/tree/MDL-26580_m20 then try and run the upgrade to see if the patch fixes the timeout issue?
          Hide
          Luis de Vasconcelos added a comment -

          Thanks. I will test again.

          Show
          Luis de Vasconcelos added a comment - Thanks. I will test again.
          Hide
          Aparup Banerjee added a comment -

          Thanks Luis, hows it going?

          Show
          Aparup Banerjee added a comment - Thanks Luis, hows it going?
          Hide
          Bruno Vernier added a comment -

          i confirm this bug is avoided for me when using Build: 20110406 and the cli method

          Show
          Bruno Vernier added a comment - i confirm this bug is avoided for me when using Build: 20110406 and the cli method
          Hide
          Luis de Vasconcelos added a comment -

          Sorry, I've had some problems getting the version from Git thanks to big-daddy internet access policies here at the office. I'm busy testing the upgrade now.

          Show
          Luis de Vasconcelos added a comment - Sorry, I've had some problems getting the version from Git thanks to big-daddy internet access policies here at the office. I'm busy testing the upgrade now.
          Hide
          Luis de Vasconcelos added a comment - - edited

          I restored an instance of my 1.9.10+ (Build: 20110112) production site on the dev server. Then I downloaded and unpacked the https://github.com/nebgor/moodle/archives/MDL-26580 codebase.

          I reset the IIS CGITimeout value in the IIS Metabase to the default setting (300) as per my production server (and the IIS defaults).

          I reset the timeout settings in the php.ini file to their default/production values:
          max_execution_time = 180
          max_input_time = 60

          I ran the MSSQL "SET READ_COMMITTED_SNAPSHOT ON" command as per the SQL Server Driver for PHP instructions.

          I did not apply any changes to the upgrade_set_timeout($max_execution_time=300) function in lib/moodlelib.php and I did not increase the value of $max_execution_time, so the default (300) was used. In other words, the code I used is the code that I downloaded from Git.

          I then upgraded the 1.9.10+ site to this test build from git. The upgrade ran for one hour and six minutes and completed without any errors. I did not experience the "Maximum execution time of 300 seconds exceeded" problem at all! I haven't yet tested the whole site thoroughly, but it looks like the "Maximum execution time of 300 seconds exceeded" problem has been resolved. The changes you have made seem to have solved the problem.

          Show
          Luis de Vasconcelos added a comment - - edited I restored an instance of my 1.9.10+ (Build: 20110112) production site on the dev server. Then I downloaded and unpacked the https://github.com/nebgor/moodle/archives/MDL-26580 codebase. I reset the IIS CGITimeout value in the IIS Metabase to the default setting (300) as per my production server (and the IIS defaults). I reset the timeout settings in the php.ini file to their default/production values: max_execution_time = 180 max_input_time = 60 I ran the MSSQL "SET READ_COMMITTED_SNAPSHOT ON" command as per the SQL Server Driver for PHP instructions. I did not apply any changes to the upgrade_set_timeout($max_execution_time=300) function in lib/moodlelib.php and I did not increase the value of $max_execution_time, so the default (300) was used. In other words, the code I used is the code that I downloaded from Git. I then upgraded the 1.9.10+ site to this test build from git. The upgrade ran for one hour and six minutes and completed without any errors. I did not experience the "Maximum execution time of 300 seconds exceeded" problem at all! I haven't yet tested the whole site thoroughly, but it looks like the "Maximum execution time of 300 seconds exceeded" problem has been resolved. The changes you have made seem to have solved the problem.
          Hide
          Aparup Banerjee added a comment -

          thanks for the test and good news!

          i've created pull requests : PULL-651 and PULL-652

          Petr, my patch doesn't touch the areas of concern so i've created MDL-27147 to address the below issues (with an excerpt from our chat)
          1/ there is a potential pref trouble in upgrade_set_timeout()
          2/ we do not need to set timeout in CLI mode at all because there is no browser to timeout

          Show
          Aparup Banerjee added a comment - thanks for the test and good news! i've created pull requests : PULL-651 and PULL-652 Petr, my patch doesn't touch the areas of concern so i've created MDL-27147 to address the below issues (with an excerpt from our chat) 1/ there is a potential pref trouble in upgrade_set_timeout() 2/ we do not need to set timeout in CLI mode at all because there is no browser to timeout
          Hide
          Luis de Vasconcelos added a comment -

          CLI mode may not have a browser to timeout, but I tried upgrading 1.9.10+ (Build: 20110112) to 2.0.2+ (Build: 20110406) via the command line (\admin\cli\upgrade.php) and still I got the following timeout error in the PHP error log:

          [13-Apr-2011 13:05:51] PHP Fatal error: Maximum execution time of 300 seconds exceeded in D:\Moodle2\lib\dml\sqlsrv_native_moodle_database.php on line 358

          php.ini was set to: max_execution_time = 180 and max_input_time = 60 so maybe it was a PHP timeout??? Or a SQL Server Driver for PHP timeout? The CGITimeout value in the IIS metabase was set to the default 300.

          But that test wasn't done against the https://github.com/nebgor/moodle/archives/MDL-26580 codebase, so I'm not worried. And the timeouts seem to be fixed by PULL-651 and PULL-652 so I'll leave this alone now! I'll test again when those pull requests have been integrated.

          Show
          Luis de Vasconcelos added a comment - CLI mode may not have a browser to timeout, but I tried upgrading 1.9.10+ (Build: 20110112) to 2.0.2+ (Build: 20110406) via the command line (\admin\cli\upgrade.php) and still I got the following timeout error in the PHP error log: [13-Apr-2011 13:05:51] PHP Fatal error: Maximum execution time of 300 seconds exceeded in D:\Moodle2\lib\dml\sqlsrv_native_moodle_database.php on line 358 php.ini was set to: max_execution_time = 180 and max_input_time = 60 so maybe it was a PHP timeout??? Or a SQL Server Driver for PHP timeout? The CGITimeout value in the IIS metabase was set to the default 300. But that test wasn't done against the https://github.com/nebgor/moodle/archives/MDL-26580 codebase, so I'm not worried. And the timeouts seem to be fixed by PULL-651 and PULL-652 so I'll leave this alone now! I'll test again when those pull requests have been integrated.
          Hide
          Aparup Banerjee added a comment -

          alright, i've created a link to MDL-27251 to resolve the files fetching timeout issue separately. see Pull-651 for details about whats been integrated.

          Show
          Aparup Banerjee added a comment - alright, i've created a link to MDL-27251 to resolve the files fetching timeout issue separately. see Pull-651 for details about whats been integrated.
          Hide
          Martin Dougiamas added a comment -

          Can this be closed? If so, please close it.

          Show
          Martin Dougiamas added a comment - Can this be closed? If so, please close it.
          Hide
          Aparup Banerjee added a comment -

          closed this. code has been integrated. the bit of code that wasn't integrated here has moved on into MDL-27251 to be worked on there.

          Show
          Aparup Banerjee added a comment - closed this. code has been integrated. the bit of code that wasn't integrated here has moved on into MDL-27251 to be worked on there.

            People

            • Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: