Moodle
  1. Moodle
  2. MDL-42815

Backup/restore: Error saving files - log messages are unhelpful

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 2.6.1, 2.7
    • Fix Version/s: 2.6.1
    • Component/s: Backup
    • Labels:
    • Testing Instructions:
      Hide

      This test requires access to the filesystem used to store the moodledata area.

      SETUP:

      1. Create a new empty course with default settings.
      2. Add a File resource to the course with name 'file to be deleted' and using the attached file willdelete.txt.
      3. Delete the following file from your test server's moodledata: filedir/15/f6/15f67f8c57f0aa224aa71461e993c2ce3cea05f4

      BACKUP:

      4. Choose Backup and proceed through backup with default settings.

      EXPECTED: On final screen the log ('Technical information and warnings') shows. This should include a line like the below (with different number and path):

      Missing file in pool: /willdelete.txt (context 334877 'File: file to be deleted', component mod_resource, filearea content, itemid 0) [/fs1/www_root/filedir/15/f6/15f67f8c57f0aa224aa71461e993c2ce3cea05f4]

      If you have developer debug on, there should be some other lines about loading controller, setting status, blah blah. Otherwise this should be the only line.

      RESTORE:

      5. Restore the backed-up file to new course using default settings.

      EXPECTED: The log ('Technical information and warnings') should show information about the missing file. This is similar to the information above except that I didn't include the context name and the filesystem location is not included/relevant. Example:

      Missing file in backup: /willdelete.txt (old context 334877, component mod_resource, filearea content, old itemid 0)

      Again, if you have developer debug turned on there should be some other lines, otherwise just this one.

      Show
      This test requires access to the filesystem used to store the moodledata area. SETUP: 1. Create a new empty course with default settings. 2. Add a File resource to the course with name 'file to be deleted' and using the attached file willdelete.txt. 3. Delete the following file from your test server's moodledata: filedir/15/f6/15f67f8c57f0aa224aa71461e993c2ce3cea05f4 BACKUP: 4. Choose Backup and proceed through backup with default settings. EXPECTED: On final screen the log ('Technical information and warnings') shows. This should include a line like the below (with different number and path): Missing file in pool: /willdelete.txt (context 334877 'File: file to be deleted', component mod_resource, filearea content, itemid 0) [/fs1/www_root/filedir/15/f6/15f67f8c57f0aa224aa71461e993c2ce3cea05f4] If you have developer debug on, there should be some other lines about loading controller, setting status, blah blah. Otherwise this should be the only line. RESTORE: 5. Restore the backed-up file to new course using default settings. EXPECTED: The log ('Technical information and warnings') should show information about the missing file. This is similar to the information above except that I didn't include the context name and the filesystem location is not included/relevant. Example: Missing file in backup: /willdelete.txt (old context 334877, component mod_resource, filearea content, old itemid 0) Again, if you have developer debug turned on there should be some other lines, otherwise just this one.
    • Affected Branches:
      MOODLE_26_STABLE, MOODLE_27_STABLE
    • Fixed Branches:
      MOODLE_26_STABLE
    • Pull Master Branch:
      MDL-42815-master

      Description

      1. When backing up a site, you may get an error at the end:

      'Some files could not be saved during the backup, it won't be possible to restore them'

      This is not very helpful as it does not list the files. A suitable place to list the files would be in the backup log, which we are now (2.6) displaying to users if there are any errors in it.

      2. When restoring the backup, you DO get a list of the affected files in the log, but the list is not in a very useful format as it basically includes only the filename and not any of the other available information.

      Note: At this stage I am not sure exactly what causes the error although I assume it's because there's something odd in the filesystem, like it doesn't have content in the file storage for certain files.

      The intent of improving this error is so that users can evaluate whether the file(s) are important and possibly go find them and fix them in the course before backing it up. The backup error is most important because by the time you're restoring, it's already too late.

      I propose to fix this as follows:

      1. Add log entry for each file that it fails to save in backup.

      2. In both the new log entry for backup, and the existing one for restore, add information about the file location (at minimum by including the numeric context ID or other IDs involved; at least in backup it might also be possible to display an activity name or something).

      Hopefully this will be a minor change.

        Gliffy Diagrams

          Issue Links

            Activity

            Hide
            Sam Marshall added a comment -

            Added testing instructions.

            I have noticed that the backup code actually does attempt to log information about the file, but that this log is not working. I think it's getting stored in an array then never used, but I'll check.

            Show
            Sam Marshall added a comment - Added testing instructions. I have noticed that the backup code actually does attempt to log information about the file, but that this log is not working. I think it's getting stored in an array then never used, but I'll check.
            Hide
            Sam Marshall added a comment -

            Turns out that the backup controller gets saved/loaded during backup process. As a result the logger is serialized and recreated, but the script still contains a reference to the existing logger, which only has log entries up to that point.

            I have a fix for this bug and am now looking at improving the reported information about the missing file.

            Show
            Sam Marshall added a comment - Turns out that the backup controller gets saved/loaded during backup process. As a result the logger is serialized and recreated, but the script still contains a reference to the existing logger, which only has log entries up to that point. I have a fix for this bug and am now looking at improving the reported information about the missing file.
            Hide
            Sam Marshall added a comment -

            Note: Part of this change fixes a bug with the backup log display in 2.6 (which was a new feature MDL-38196) in which it didn't display log messages after a certain point. However I don't think this is a very serious bug so it should be OK to leave it broken until 2.6.1.

            Show
            Sam Marshall added a comment - Note: Part of this change fixes a bug with the backup log display in 2.6 (which was a new feature MDL-38196 ) in which it didn't display log messages after a certain point. However I don't think this is a very serious bug so it should be OK to leave it broken until 2.6.1.
            Hide
            Dan Poltawski added a comment -

            Thanks Sam, sending for integration

            Show
            Dan Poltawski added a comment - Thanks Sam, sending for integration
            Hide
            Eloy Lafuente (stronk7) added a comment -

            Integrated (26 and master), thanks!

            PS: The only point I'm not entirely happy is the assumption of the "core_backup_html_logger" being there always... I think it's possible to change loggers availability in the future... nvm, not critical for now.

            Show
            Eloy Lafuente (stronk7) added a comment - Integrated (26 and master), thanks! PS: The only point I'm not entirely happy is the assumption of the "core_backup_html_logger" being there always... I think it's possible to change loggers availability in the future... nvm, not critical for now.
            Hide
            Mark Nelson added a comment -

            Thanks Sam, works as expected.

            I did find one issue MDL-43335, but it is not related to this patch, so all good.

            Show
            Mark Nelson added a comment - Thanks Sam, works as expected. I did find one issue MDL-43335 , but it is not related to this patch, so all good.
            Hide
            Sam Marshall added a comment -

            Thanks both.

            Eloy - regarding this specific change, the core_backup_html_logger will always be there because it was created and added about 5 lines before, inside the same backup.php script. You can't see it in the default context of the github diff view but it's there if you expand upwards. The new code just finds the existing logger.

            Show
            Sam Marshall added a comment - Thanks both. Eloy - regarding this specific change, the core_backup_html_logger will always be there because it was created and added about 5 lines before, inside the same backup.php script. You can't see it in the default context of the github diff view but it's there if you expand upwards. The new code just finds the existing logger.
            Hide
            Eloy Lafuente (stronk7) added a comment -

            Yeah, yeah, Sam. I saw it... I just was imagining that it may be possible to alter the loggers chain in the middle causing that one to not being available at the end of the process.

            More exactly I was thinking about backup_factory::get_logger_chain(), where various CFG settings can be altering the default loggers, supposing that it may be possible to avoid/already-have some other html logger preventing yours to be added. But after looking to that method with more attention, it's a 99.999% unlikely case (nor I think anybody will be doing that in the middle of the execution).

            Thanks and ciao

            Show
            Eloy Lafuente (stronk7) added a comment - Yeah, yeah, Sam. I saw it... I just was imagining that it may be possible to alter the loggers chain in the middle causing that one to not being available at the end of the process. More exactly I was thinking about backup_factory::get_logger_chain(), where various CFG settings can be altering the default loggers, supposing that it may be possible to avoid/already-have some other html logger preventing yours to be added. But after looking to that method with more attention, it's a 99.999% unlikely case (nor I think anybody will be doing that in the middle of the execution). Thanks and ciao
            Hide
            Sam Hemelryk added a comment -

            Thanks for the code, its now upstream!

            Heres a fun trick to try in the spirit of Friday the 13th.
            I hear if you stand in front a mirror, alone, in the dark, and say "Oracle" three times Petr Skoka will appear in the mirror and you'll see him deleting the Oracle driver from Moodle.

            Show
            Sam Hemelryk added a comment - Thanks for the code, its now upstream! Heres a fun trick to try in the spirit of Friday the 13th. I hear if you stand in front a mirror, alone, in the dark, and say "Oracle" three times Petr Skoka will appear in the mirror and you'll see him deleting the Oracle driver from Moodle.

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: