Menu
▾
▴
[Bacula-bugs] [bacula 0000402]: Backup records wrong order of volumes, tape-spanning files truncated during restore
|
From: <bac...@li...> - 2005-09-13 18:54:47
|
The following bug has been CLOSED ====================================================================== http://bugs.bacula.org/bug_view_advanced_page.php?bug_id=0000402 ====================================================================== Reported By: awui Assigned To: ====================================================================== Project: bacula Bug ID: 402 Category: Director Reproducibility: sometimes Severity: major Priority: urgent Status: closed ====================================================================== Date Submitted: 08-16-2005 08:18 PDT Last Modified: 09-13-2005 11:54 PDT ====================================================================== Summary: Backup records wrong order of volumes, tape-spanning files truncated during restore Description: For backups spanning more than one tape, a job may report Volume name(s) in an order different from the order in which the volumes were actually written. During restore, volumes are read in this order. A file spanning over two tapes is truncated if the tail-part volume is read before the head-part volume, in which case only the head contents of the file are restored. ====================================================================== ---------------------------------------------------------------------- kern - 08-18-2005 06:58 PDT ---------------------------------------------------------------------- This report surprises me because the code *explicitly* attempts to keep the volumes in order. The oldest Bacula I have loaded is 1.36.3, so I am reasonably sure that the code also exists in version 1.36.1. To resolve the problem, I'll need the following: - A case where you can reproduce the problem. - The Job output from the backup - A copy of the bootstrap file produced for restore (copy it at the point of the yes/mod/no prompt at the end of the restore dialog). - The Job output from the restore. However, before doing all this, look at the file: src/cats/sql_get.c In the subroutine db_get_job_volume_names() there should be a reference to sorting on VolIndex, and in the subroutine db_get_job_volume_parameters(), the first SQL SELECT command should have ORDER BY VolIndex, ... If these are not true, then you will need to upgrade to 1.36.3. If they are true, then something is going wrong in the process and I'll need the above info for a start. ---------------------------------------------------------------------- awui - 08-18-2005 11:09 PDT ---------------------------------------------------------------------- Kern, thanks for the response - the ZIP file provided with the initial report contains backup/restore log files for two examples of failed attempts with two and three tapes, respectively, and one example with two tapes that restored correctly. I have attached the sgl_get.c excerpts of our current installation, which seem to include the SQL parts that should take care of the sorting. In further investigation, we queried PostgreSQL directly for the entries relating to Job 11 (backup spanning across three tapes) with sorting applied and also including the VolIndex entries. The correct order of volumes should have been Full-0005, Full-0004, Full-0002; sorting by VolIndex results in Full-0004, Full-0002, Full-0005 order, thus the VolIndexes were already incorrectly recorded in the SQL database. Note that the firstindex/lastindex entries reflect the correct ordering of the tapes. Maybe this helps in narrowing down the problem. ---------------------------------------------------------------------- kern - 08-18-2005 11:47 PDT ---------------------------------------------------------------------- The SQL code you have corresponds to mine, so that should not be the problem. Can you attach a list of the JobMedia records as a .txt file with the VolIndex column included? It appears that either something is going wrong in inserting the VolIndex items, or the sort is not working correctly. ---------------------------------------------------------------------- awui - 08-18-2005 12:08 PDT ---------------------------------------------------------------------- > Can you attach a list of the JobMedia records as a .txt file with the > VolIndex column included? - done, the .log version was malformatted in the process ... ---------------------------------------------------------------------- kern - 08-19-2005 02:09 PDT ---------------------------------------------------------------------- As you mentioned the last time, the VolIndex is not right. It is computed from: SELECT count(*) from JobMedia; so I cannot see how it could possibly end up with the values you have unless you deleted a job during the backup or some pruning happened. Is that possible? I cannot think of any other reason why the VolIndex would be out of order. In otherwords what would cause the total number of JobMedia records to decrease. In thinking about this a bit, I think the above select statement could be much improved and made independent of job deletion or pruning by changing it to be: Mmsg(mdb->cmd, "SELECT count(*) from JobMedia WHERE JobId=%s", edit_int64(jm->JobId, ed1)); Actually, this value (VolIndex) needs only to be incremented when a new MediaId is being added, but I cannot think of any simple efficient way to do that. The above code is at the very top of the subroutine db_create_jobmedia_record() in src/cats/sql_create.c. I am making the change to my code and testing it, I would appreciate it if you would do the same. ---------------------------------------------------------------------- awui - 08-19-2005 10:19 PDT ---------------------------------------------------------------------- I had another look into the log file to figure out what happened before the three-tape test (Job 11) that recorded the wrong order. A backup performed on the previous day had been cancelled, and immediately before recycling the Full-0004 volume, it was pruning 1 Job on Full-0001 and 3 Jobs on Full-0003 from catalog (these parts are not in the log snippets of our initial report; Full-0001 was the last tape written during the aborted backup, but neither Full-0001/0003 volumes were used for the failed backup; Full-0002 was written during the aborted backup and recycled as the last volume for Job 11). I found the sql_create.c command line, currently reading "SELECT count(*) from JobMedia" only. Since we have to recompile the daemons anyway for further investigation and seem to have a rather old version, we discussed to get more recent sources, make the modification you suggested, and then try again what happens. If you have any other testing scenario, we will be happy to try; obviously, the cancelled backup and the timing of the pruning may have had an impact. ---------------------------------------------------------------------- kern - 08-19-2005 12:18 PDT ---------------------------------------------------------------------- Ideally, you would run a backup with the old code and observe the problem. You would then make the modification that I suggested and run again observing that the problem is fixed. Given what you have said, this may not be possible. However, what you describe as happening during the backup could well be what triggered seeing the bug. I've tested here with the new code on 1.37.36 and it passes all my regression tests, including the two volume tests, so I think the possibility of it causing some problems is pretty low. Also the probability that it fixes the bug is pretty high ... Let me know when you have done your testing. Thanks. ---------------------------------------------------------------------- awui - 08-23-2005 15:25 PDT ---------------------------------------------------------------------- We have upgraded our version to 1.37.36, but left the "SELECT count(*) from JobMedia" in sql_create.c for now; we will try to find a scenario that breaks it and causes the tapes to be VolIndex-ed in the wrong order, while we are not certain if we can reproduce that easily. If it breaks, but works then with your last week's patch, this should be the solution. If we can't break it, we will just apply the patch anyway and keep monitoring that everything holds then for sure. I'll post a follow-up within the next few days on the results ... ---------------------------------------------------------------------- awui - 08-29-2005 14:28 PDT ---------------------------------------------------------------------- We could reproduce the problem in 1.37.36 (August 18 build): - database table was set up from scratch, with six volumes labelled - first backup was written on volumes 1 and 2 - catalog backups proceeded inbetween as scheduled - a backup was started and cancelled to create unfinished job entries - second backup was written on volumes 6, 2, 3 - second backup was correctly restored - then we set the retention period for tapes 1 and 2 to allow recycling - third backup (Job 11 in new counting, attached): -- starts with filling volumes 3, 4, 5 -- notices that it is running out of volumes -- recycles volumes 1 and 2 -- no user intervention was required even though bacula was asking for it (?) -- writes remainder to volume 1 -- records wrong volume order 1, 3, 4, 5 instead of 3, 4, 5, 1 - restore of third backup left the file which is spanning from volume 5 into volume 1 corrupted -- in contrast to 1.36.1, which was reporting a restore error, version 1.37.36 claims restore ok. The SQL output from postgres is attached, again showing a wrong order of VolIndex entries consistent with the 1.36.1 test. We will now apply your patch for sql_create.c, drop all tables, and try to reproduce the same scenario to verify that the patch solves the problem. ---------------------------------------------------------------------- awui - 09-13-2005 08:40 PDT ---------------------------------------------------------------------- We have replicated the scenario that previously caused the wrong order of volumes, now with the patch for sql_create.c applied to version 1.37.36; as can be seen from the attached backup/restore log and the psql output, the order of the volumes is now correct (volumes 6, 2, 3, 4) despite job pruning and volume recycling during the backup. Also, the VolIndex entries show the correct order. Thus, it seems that the patch fixed the bug, thanks for your help! ---------------------------------------------------------------------- kern - 09-13-2005 11:54 PDT ---------------------------------------------------------------------- Thanks for your careful testing of this problem. I appreciate you confirming the fix. Please consider upgrading to 1.37.38, where I have applied yet another fix (quite different code) to prevent the same out of order Volumes when multiple Jobs are involved (e.g. Full, Diff, Inc used in a restore). Bug History Date Modified Username Field Change ====================================================================== 08-16-05 08:18 awui New Bug 08-16-05 08:18 awui File Added: bacula-tests.zip 08-16-05 08:22 awui Bug Monitored: awui 08-18-05 06:58 kern Bugnote Added: 0001109 08-18-05 06:58 kern Status new => feedback 08-18-05 10:58 awui File Added: sql_get_snippet.txt 08-18-05 10:59 awui File Added: three-tapes-psql.log 08-18-05 11:09 awui Bugnote Added: 0001113 08-18-05 11:47 kern Bugnote Added: 0001114 08-18-05 12:06 awui File Added: three-tapes-psql.txt 08-18-05 12:08 awui Bugnote Added: 0001115 08-19-05 02:09 kern Bugnote Added: 0001117 08-19-05 02:11 kern Priority normal => urgent 08-19-05 10:19 awui Bugnote Added: 0001125 08-19-05 12:18 kern Bugnote Added: 0001126 08-23-05 15:25 awui Bugnote Added: 0001127 08-29-05 14:28 awui Bugnote Added: 0001133 08-29-05 14:29 awui File Added: four-tape-backup-failed.txt 08-29-05 14:30 awui File Added: four-tape-restore-failed.txt 08-29-05 14:30 awui File Added: four-tape-psql-volindex.txt 09-13-05 08:40 awui Bugnote Added: 0001154 09-13-05 08:41 awui File Added: four-tape-with-patch.txt 09-13-05 08:41 awui File Added: four-tape-psql-patch.txt 09-13-05 11:54 kern Bugnote Added: 0001156 09-13-05 11:54 kern Resolution open => fixed 09-13-05 11:54 kern Status feedback => closed ====================================================================== |