From 53f95c99cbf141633c8374f846d993cf200b4da8 Mon Sep 17 00:00:00 2001 From: "Eloy Lafuente (stronk7)" Date: Wed, 11 May 2016 23:57:54 +0200 Subject: [PATCH 1/4] MDL-54205 backup: loggers close() and destroy() Any backup & restore operation may be leaving opened files if a file logger is being used. This implementes the close() method, so every logger can close any resource. Also, the recommended backup_controlled::destroy() method now calls to new logger::destroy() method in charge of deleting all the references and closing any resource. Finally, some internally used controllers, were missing their destroy call, leading to associated loggers to remain open. Now all them are explicitly deltroyed. --- backup/controller/backup_controller.class.php | 4 +++- .../controller/restore_controller.class.php | 4 +++- backup/upgrade.txt | 8 +++++++ backup/util/dbops/restore_dbops.class.php | 10 ++++++-- backup/util/helper/backup_helper.class.php | 1 + backup/util/loggers/base_logger.class.php | 24 +++++++++++++++++++ backup/util/loggers/file_logger.class.php | 13 ++++++++++ 7 files changed, 60 insertions(+), 4 deletions(-) diff --git a/backup/controller/backup_controller.class.php b/backup/controller/backup_controller.class.php index e270f9e1f86..35edd9c318a 100644 --- a/backup/controller/backup_controller.class.php +++ b/backup/controller/backup_controller.class.php @@ -158,6 +158,8 @@ class backup_controller extends base_controller { public function destroy() { // Only need to destroy circulars under the plan. Delegate to it. $this->plan->destroy(); + // Loggers may have also chained references, destroy them. Also closing resources when needed. + $this->logger->destroy(); } public function finish_ui() { @@ -184,7 +186,7 @@ class backup_controller extends base_controller { $this->save_controller(); $tbc = self::load_controller($this->backupid); $this->logger = $tbc->logger; // wakeup loggers - $tbc->destroy(); // Clean temp controller structures + $tbc->plan->destroy(); // Clean plan controller structures, keeping logger alive. } else if ($status == backup::STATUS_FINISHED_OK) { // If the operation has ended without error (backup::STATUS_FINISHED_OK) diff --git a/backup/controller/restore_controller.class.php b/backup/controller/restore_controller.class.php index 8c72c588359..2829b998766 100644 --- a/backup/controller/restore_controller.class.php +++ b/backup/controller/restore_controller.class.php @@ -170,6 +170,8 @@ class restore_controller extends base_controller { public function destroy() { // Only need to destroy circulars under the plan. Delegate to it. $this->plan->destroy(); + // Loggers may have also chained references, destroy them. Also closing resources when needed. + $this->logger->destroy(); } public function finish_ui() { @@ -196,7 +198,7 @@ class restore_controller extends base_controller { $this->save_controller(); $tbc = self::load_controller($this->restoreid); $this->logger = $tbc->logger; // wakeup loggers - $tbc->destroy(); // Clean temp controller structures + $tbc->plan->destroy(); // Clean plan controller structures, keeping logger alive. } else if ($status == backup::STATUS_FINISHED_OK) { // If the operation has ended without error (backup::STATUS_FINISHED_OK) diff --git a/backup/upgrade.txt b/backup/upgrade.txt index 31e7f031106..88a9c885691 100644 --- a/backup/upgrade.txt +++ b/backup/upgrade.txt @@ -1,6 +1,14 @@ This files describes API changes in /backup/*, information provided here is intended especially for developers. +=== 3.1 === + +* New close() method added to loggers so they can close any open resource. Previously + any backup and restore operation using the file logger may be leaving unclosed files. +* New destroy() method added to loggers, normally called from backup and restore controllers + own destroy() method to ensure that all references in the chained loggers are deleted + and any open resource within them is closed properly. + === 3.0 === * The backup_auto_keep setting, in automated backups configuration, is now diff --git a/backup/util/dbops/restore_dbops.class.php b/backup/util/dbops/restore_dbops.class.php index 120ea6c7d4e..6d48d36ea9c 100644 --- a/backup/util/dbops/restore_dbops.class.php +++ b/backup/util/dbops/restore_dbops.class.php @@ -101,9 +101,11 @@ abstract class restore_dbops { // If included, add it if ($included) { - $includedtasks[] = $task; + $includedtasks[] = clone($task); // A clone is enough. In fact we only need the basepath. } } + $rc->destroy(); // Always need to destroy. + return $includedtasks; } @@ -1510,8 +1512,12 @@ abstract class restore_dbops { // Calculate the context we are going to use for capability checking $context = context_course::instance($courseid); + // TODO: Some day we must kill this dependency and change the process + // to pass info around without loading a controller copy. // When conflicting users are detected we may need original site info. - $restoreinfo = restore_controller_dbops::load_controller($restoreid)->get_info(); + $rc = restore_controller_dbops::load_controller($restoreid); + $restoreinfo = $rc->get_info(); + $rc->destroy(); // Always need to destroy. // Calculate if we have perms to create users, by checking: // to 'moodle/restore:createuser' and 'moodle/restore:userinfo' diff --git a/backup/util/helper/backup_helper.class.php b/backup/util/helper/backup_helper.class.php index 4096371b765..a5a7faa0fb5 100644 --- a/backup/util/helper/backup_helper.class.php +++ b/backup/util/helper/backup_helper.class.php @@ -302,6 +302,7 @@ abstract class backup_helper { $bc = backup_controller::load_controller($backupid); $bc->log('Attempt to copy backup file to the specified directory using filesystem failed - ', backup::LOG_WARNING, $dir); + $bc->destroy(); } // bad luck, try to deal with the file the old way - keep backup in file area if we can not copy to ext system } diff --git a/backup/util/loggers/base_logger.class.php b/backup/util/loggers/base_logger.class.php index ed2125cf37e..32b0c06c939 100644 --- a/backup/util/loggers/base_logger.class.php +++ b/backup/util/loggers/base_logger.class.php @@ -71,6 +71,30 @@ abstract class base_logger implements checksumable { return $this->level; } + /** + * Destroy (nullify) the chain of loggers references, also closing resources when needed. + * + * @since Moodle 3.1 + */ + public final function destroy() { + // Recursively destroy the chain. + if ($this->next !== null) { + $this->next->destroy(); + $this->next = null; + } + // And close every logger. + $this->close(); + } + + /** + * Close any resource the logger may have open. + * + * @since Moodle 3.1 + */ + public function close() { + // Nothing to do by default. Only loggers using resources (files, own connections...) need to override this. + } + // checksumable interface methods public function calculate_checksum() { diff --git a/backup/util/loggers/file_logger.class.php b/backup/util/loggers/file_logger.class.php index 5c05380d36f..98ff74acf39 100644 --- a/backup/util/loggers/file_logger.class.php +++ b/backup/util/loggers/file_logger.class.php @@ -66,6 +66,19 @@ class file_logger extends base_logger { } } + /** + * Close the logger resources (file handle) if still open. + * + * @since Moodle 3.1 + */ + public function close() { + // Close the file handle if hasn't been closed already. + if (is_resource($this->fhandle)) { + fclose($this->fhandle); + $this->fhandle = null; + } + } + // Protected API starts here protected function action($message, $level, $options = null) { From da322ad078c1b9ea8302bd0f72ecbd1d0c4f7962 Mon Sep 17 00:00:00 2001 From: "Eloy Lafuente (stronk7)" Date: Thu, 12 May 2016 22:55:34 +0200 Subject: [PATCH 2/4] MDL-54205 tool_recyclebin: Adding missing destroy() calls. This was causing controller references not cleaned till gc and loggers to remain open, leading to problems under windows. --- admin/tool/recyclebin/classes/category_bin.php | 6 ++++++ admin/tool/recyclebin/classes/course_bin.php | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/admin/tool/recyclebin/classes/category_bin.php b/admin/tool/recyclebin/classes/category_bin.php index 06b06de1601..2acb3b2c679 100644 --- a/admin/tool/recyclebin/classes/category_bin.php +++ b/admin/tool/recyclebin/classes/category_bin.php @@ -126,6 +126,9 @@ class category_bin extends base_bin { throw new \moodle_exception('Failed to backup activity prior to deletion.'); } + // Have finished with the controller, let's destroy it, freeing mem and resources. + $controller->destroy(); + // Grab the filename. $file = $result['backup_destination']; if (!$file->get_contenthash()) { @@ -259,6 +262,9 @@ class category_bin extends base_bin { // Run the import. $controller->execute_plan(); + // Have finished with the controller, let's destroy it, freeing mem and resources. + $controller->destroy(); + // Fire event. $event = \tool_recyclebin\event\category_bin_item_restored::create(array( 'objectid' => $item->id, diff --git a/admin/tool/recyclebin/classes/course_bin.php b/admin/tool/recyclebin/classes/course_bin.php index a05a7cfd845..67e1a21eccd 100644 --- a/admin/tool/recyclebin/classes/course_bin.php +++ b/admin/tool/recyclebin/classes/course_bin.php @@ -130,6 +130,9 @@ class course_bin extends base_bin { throw new \moodle_exception('Failed to backup activity prior to deletion.'); } + // Have finished with the controller, let's destroy it, freeing mem and resources. + $controller->destroy(); + // Grab the filename. $file = $result['backup_destination']; if (!$file->get_contenthash()) { @@ -246,6 +249,9 @@ class course_bin extends base_bin { // Run the import. $controller->execute_plan(); + // Have finished with the controller, let's destroy it, freeing mem and resources. + $controller->destroy(); + // Fire event. $event = \tool_recyclebin\event\course_bin_item_restored::create(array( 'objectid' => $item->id, From fcd3bbfee031dddf739dbf65d21bb70886f324be Mon Sep 17 00:00:00 2001 From: "Eloy Lafuente (stronk7)" Date: Fri, 13 May 2016 01:46:48 +0200 Subject: [PATCH 3/4] MDL-54205 tests: verify destroy() and close() behavior --- backup/util/loggers/tests/logger_test.php | 22 +++++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/backup/util/loggers/tests/logger_test.php b/backup/util/loggers/tests/logger_test.php index 67f8e7472c6..70a65f9b8b3 100644 --- a/backup/util/loggers/tests/logger_test.php +++ b/backup/util/loggers/tests/logger_test.php @@ -108,6 +108,16 @@ class backup_logger_testcase extends basic_testcase { $this->assertEquals($lo1->get_levelstr(backup::LOG_WARNING), 'warn'); $this->assertEquals($lo1->get_levelstr(backup::LOG_INFO), 'info'); $this->assertEquals($lo1->get_levelstr(backup::LOG_DEBUG), 'debug'); + + // Test destroy. + $lo1 = new mock_base_logger1(backup::LOG_ERROR); + $lo2 = new mock_base_logger2(backup::LOG_ERROR); + $lo1->set_next($lo2); + $this->assertInstanceOf('base_logger', $lo1->get_next()); + $this->assertNull($lo2->get_next()); + $lo1->destroy(); + $this->assertNull($lo1->get_next()); + $this->assertNull($lo2->get_next()); } /** @@ -249,9 +259,9 @@ class backup_logger_testcase extends basic_testcase { $result = $lo2->process($message2, backup::LOG_WARNING, $options); $this->assertTrue($result); - // Destruct loggers - $lo1 = null; - $lo2 = null; + // Destroy loggers. + $lo1->destroy(); + $lo2->destroy(); // Load file results to analyze them $fcontents = file_get_contents($file); @@ -275,6 +285,7 @@ class backup_logger_testcase extends basic_testcase { $this->assertTrue(file_exists($file)); $message = 'testing file_logger'; $result = $lo->process($message, backup::LOG_ERROR, $options); + $lo->close(); // Closes logger. // Get file contents and inspect them $fcontents = file_get_contents($file); $this->assertTrue($result); @@ -282,7 +293,6 @@ class backup_logger_testcase extends basic_testcase { $this->assertTrue(strpos($fcontents, '[error]') !== false); $this->assertTrue(strpos($fcontents, '  ') !== false); $this->assertTrue(substr_count($fcontents , '] ') >= 2); - $lo->__destruct(); // closes file handle unlink($file); // delete file // Instantiate, write something, force deletion, try to write again @@ -292,7 +302,8 @@ class backup_logger_testcase extends basic_testcase { $this->assertTrue(file_exists($file)); $message = 'testing file_logger'; $result = $lo->process($message, backup::LOG_ERROR); - fclose($lo->get_fhandle()); // close file + $lo->close(); + $this->assertNull($lo->get_fhandle()); try { $result = @$lo->process($message, backup::LOG_ERROR); // Try to write again $this->assertTrue(false, 'base_logger_exception expected'); @@ -326,6 +337,7 @@ class backup_logger_testcase extends basic_testcase { $lo = new file_logger(backup::LOG_NONE, true, true, $file); $this->assertTrue($lo instanceof file_logger); $this->assertFalse(file_exists($file)); + $lo->close(); // Remove the test dir and any content @remove_dir(dirname($file)); From 07a069f1c0985dde2be4e0e2f1a1c5b9a17045d4 Mon Sep 17 00:00:00 2001 From: "Eloy Lafuente (stronk7)" Date: Fri, 13 May 2016 02:50:45 +0200 Subject: [PATCH 4/4] MDL-50063 unittests: Remove some unnecesary gc_collect_cycles() Now backup and restore operations free logger resources calling to the destroy() method. This commit ensures: 1) That gc_collect_cycles() is not used anymore in backup-related tests. 2) That all backup and restore controllers in test do always call to the detroy() method. 3) Some unset() calls, needed to make gc_collect_cycles() are not used anymore. --- admin/tool/uploadcourse/classes/course.php | 1 - admin/tool/uploadcourse/tests/course_test.php | 7 ------- admin/tool/uploadcourse/tests/helper_test.php | 2 -- admin/tool/uploadcourse/tests/processor_test.php | 7 ------- backup/moodle2/tests/moodle2_course_format_test.php | 9 +-------- backup/moodle2/tests/moodle2_test.php | 12 ------------ backup/util/checks/tests/checks_test.php | 1 + backup/util/plan/tests/plan_test.php | 2 ++ backup/util/plan/tests/step_test.php | 3 +++ backup/util/plan/tests/task_test.php | 1 + course/tests/courselib_test.php | 9 --------- course/tests/externallib_test.php | 7 ------- lib/tests/questionlib_test.php | 10 ++-------- 13 files changed, 10 insertions(+), 61 deletions(-) diff --git a/admin/tool/uploadcourse/classes/course.php b/admin/tool/uploadcourse/classes/course.php index 4486cdebb5c..7b111cb9d35 100644 --- a/admin/tool/uploadcourse/classes/course.php +++ b/admin/tool/uploadcourse/classes/course.php @@ -740,7 +740,6 @@ class tool_uploadcourse_course { $this->error('errorwhilerestoringcourse', new lang_string('errorwhilerestoringthecourse', 'tool_uploadcourse')); } $rc->destroy(); - unset($rc); // File logging is a mess, we can only try to rely on gc to close handles. } // Proceed with enrolment data. diff --git a/admin/tool/uploadcourse/tests/course_test.php b/admin/tool/uploadcourse/tests/course_test.php index 20bbaa352df..0b62e87938b 100644 --- a/admin/tool/uploadcourse/tests/course_test.php +++ b/admin/tool/uploadcourse/tests/course_test.php @@ -35,13 +35,6 @@ global $CFG; */ class tool_uploadcourse_course_testcase extends advanced_testcase { - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - public function test_proceed_without_prepare() { $this->resetAfterTest(true); $mode = tool_uploadcourse_processor::MODE_CREATE_NEW; diff --git a/admin/tool/uploadcourse/tests/helper_test.php b/admin/tool/uploadcourse/tests/helper_test.php index 41a838c1753..67685074665 100644 --- a/admin/tool/uploadcourse/tests/helper_test.php +++ b/admin/tool/uploadcourse/tests/helper_test.php @@ -129,7 +129,6 @@ class tool_uploadcourse_helper_testcase extends advanced_testcase { $this->assertTrue(isset($result['backup_destination'])); $c1backupfile = $result['backup_destination']->copy_content_to_temp(); $bc->destroy(); - unset($bc); // File logging is a mess, we can only try to rely on gc to close handles. // Creating backup file. $bc = new backup_controller(backup::TYPE_1COURSE, $c2->id, backup::FORMAT_MOODLE, @@ -139,7 +138,6 @@ class tool_uploadcourse_helper_testcase extends advanced_testcase { $this->assertTrue(isset($result['backup_destination'])); $c2backupfile = $result['backup_destination']->copy_content_to_temp(); $bc->destroy(); - unset($bc); // File logging is a mess, we can only try to rely on gc to close handles. $oldcfg = isset($CFG->keeptempdirectoriesonbackup) ? $CFG->keeptempdirectoriesonbackup : false; $CFG->keeptempdirectoriesonbackup = true; diff --git a/admin/tool/uploadcourse/tests/processor_test.php b/admin/tool/uploadcourse/tests/processor_test.php index 2d2ec04456b..1dd20dc1927 100644 --- a/admin/tool/uploadcourse/tests/processor_test.php +++ b/admin/tool/uploadcourse/tests/processor_test.php @@ -36,13 +36,6 @@ require_once($CFG->libdir . '/csvlib.class.php'); */ class tool_uploadcourse_processor_testcase extends advanced_testcase { - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - public function test_basic() { global $DB; $this->resetAfterTest(true); diff --git a/backup/moodle2/tests/moodle2_course_format_test.php b/backup/moodle2/tests/moodle2_course_format_test.php index 47b9971c62d..bac585934bf 100644 --- a/backup/moodle2/tests/moodle2_course_format_test.php +++ b/backup/moodle2/tests/moodle2_course_format_test.php @@ -39,13 +39,6 @@ require_once($CFG->libdir . '/completionlib.php'); */ class core_backup_moodle2_course_format_testcase extends advanced_testcase { - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - /** * Tests a backup and restore adds the required section option data * when the same course format is used. @@ -269,4 +262,4 @@ class format_test_cs2_options extends format_test_cs_options { ), ) + parent::section_format_options($foreditform); } -} \ No newline at end of file +} diff --git a/backup/moodle2/tests/moodle2_test.php b/backup/moodle2/tests/moodle2_test.php index 4842d4a8d18..52310825a21 100644 --- a/backup/moodle2/tests/moodle2_test.php +++ b/backup/moodle2/tests/moodle2_test.php @@ -38,13 +38,6 @@ require_once($CFG->libdir . '/completionlib.php'); */ class core_backup_moodle2_testcase extends advanced_testcase { - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - /** * Tests the availability field on modules and sections is correctly * backed up and restored. @@ -161,11 +154,6 @@ class core_backup_moodle2_testcase extends advanced_testcase { $thrown->getFile() . ':' . $thrown->getLine(). "]\n\n"; } - // Must set restore_controller variable to null so that php - // garbage-collects it; otherwise the file will be left open and - // attempts to delete it will cause a permission error on Windows - // systems, breaking unit tests. - $rc = null; $this->assertNull($thrown); // Get information about the resulting course and check that it is set diff --git a/backup/util/checks/tests/checks_test.php b/backup/util/checks/tests/checks_test.php index 6bcbda4f198..8e4ced3e7e3 100644 --- a/backup/util/checks/tests/checks_test.php +++ b/backup/util/checks/tests/checks_test.php @@ -131,6 +131,7 @@ class backup_check_testcase extends advanced_testcase { backup::INTERACTIVE_NO, backup::MODE_GENERAL, $this->userid); $this->assertTrue(backup_check::check_security($bc, true)); $this->assertTrue($bc instanceof backup_controller); + $bc->destroy(); } } diff --git a/backup/util/plan/tests/plan_test.php b/backup/util/plan/tests/plan_test.php index bfc98f301a4..3e9b2feb1f7 100644 --- a/backup/util/plan/tests/plan_test.php +++ b/backup/util/plan/tests/plan_test.php @@ -89,6 +89,8 @@ class backup_plan_testcase extends advanced_testcase { // Calculate checksum and check it $checksum = $bp->calculate_checksum(); $this->assertTrue($bp->is_checksum_correct($checksum)); + + $bc->destroy(); } /** diff --git a/backup/util/plan/tests/step_test.php b/backup/util/plan/tests/step_test.php index 826b349d990..0b1ba6db556 100644 --- a/backup/util/plan/tests/step_test.php +++ b/backup/util/plan/tests/step_test.php @@ -88,6 +88,7 @@ class backup_step_testcase extends advanced_testcase { $this->assertTrue($bs instanceof backup_step); $this->assertEquals($bs->get_name(), 'stepname'); + $bc->destroy(); } /** @@ -128,6 +129,8 @@ class backup_step_testcase extends advanced_testcase { $this->assertTrue(strpos($contents, 'value2') !== false); $this->assertTrue(strpos($contents, '') !== false); + $bc->destroy(); + unlink($file); // delete file // Remove the test dir and any content diff --git a/backup/util/plan/tests/task_test.php b/backup/util/plan/tests/task_test.php index efc1b6011a2..40ee6ead97c 100644 --- a/backup/util/plan/tests/task_test.php +++ b/backup/util/plan/tests/task_test.php @@ -93,6 +93,7 @@ class backup_task_testcase extends advanced_testcase { $checksum = $bt->calculate_checksum(); $this->assertTrue($bt->is_checksum_correct($checksum)); + $bc->destroy(); } /** diff --git a/course/tests/courselib_test.php b/course/tests/courselib_test.php index 26400e37a96..f0d4869de70 100644 --- a/course/tests/courselib_test.php +++ b/course/tests/courselib_test.php @@ -32,13 +32,6 @@ require_once($CFG->dirroot . '/enrol/imsenterprise/tests/imsenterprise_test.php' class core_course_courselib_testcase extends advanced_testcase { - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - /** * Set forum specific test values for calling create_module(). * @@ -1917,7 +1910,6 @@ class core_course_courselib_testcase extends advanced_testcase { $filepath = $CFG->dataroot . '/temp/backup/test-restore-course-event'; $file->extract_to_pathname($fp, $filepath); $bc->destroy(); - unset($bc); // Now we want to catch the restore course event. $sink = $this->redirectEvents(); @@ -1955,7 +1947,6 @@ class core_course_courselib_testcase extends advanced_testcase { // Destroy the resource controller since we are done using it. $rc->destroy(); - unset($rc); } /** diff --git a/course/tests/externallib_test.php b/course/tests/externallib_test.php index 9ca911bbd71..9ad5d73aab3 100644 --- a/course/tests/externallib_test.php +++ b/course/tests/externallib_test.php @@ -47,13 +47,6 @@ class core_course_externallib_testcase extends externallib_advanced_testcase { require_once($CFG->dirroot . '/course/externallib.php'); } - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - /** * Test create_categories */ diff --git a/lib/tests/questionlib_test.php b/lib/tests/questionlib_test.php index 16350107d16..969e4873702 100644 --- a/lib/tests/questionlib_test.php +++ b/lib/tests/questionlib_test.php @@ -51,13 +51,6 @@ class core_questionlib_testcase extends advanced_testcase { $this->resetAfterTest(); } - /** - * Tidy up open files that may be left open. - */ - protected function tearDown() { - gc_collect_cycles(); - } - /** * Return true and false to test functions with feedback on and off. * @@ -248,7 +241,6 @@ class core_questionlib_testcase extends advanced_testcase { $filepath = $CFG->dataroot . '/temp/backup/test-restore-course'; $file->extract_to_pathname($fp, $filepath); $bc->destroy(); - unset($bc); // Now restore the course. $rc = new restore_controller('test-restore-course', $course2->id, backup::INTERACTIVE_NO, @@ -262,6 +254,8 @@ class core_questionlib_testcase extends advanced_testcase { // Check that there are two questions in the restored to course's context. $this->assertEquals(2, $DB->count_records('question', array('category' => $restoredcategory->id))); + + $rc->destroy(); } /**