From: Mantis B. T. <bac...@li...> - 2008-12-20 20:08:06
|
A NOTE has been added to this issue. ====================================================================== http://bugs.bacula.org/view.php?id=1194 ====================================================================== Reported By: jesperkrogh Assigned To: ====================================================================== Project: bacula Issue ID: 1194 Category: Director Reproducibility: always Severity: minor Priority: normal Status: feedback ====================================================================== Date Submitted: 2008-11-24 15:55 UTC Last Modified: 2008-12-20 20:07 UTC ====================================================================== Summary: Restore fails when not available tape is supposed to be used. Description: Doing a restore today .. the selected set was from a tape not currently in the changer, so bacula requests operator intervention. We put in the tape and mtx -f /dev/changer status showed the tape, mtx-changer /dev/changer list showed the tape and the concole reported: Catalog record for Volume "000723L3" updated to reference slot 134 For the tape needed. But doing a mount drive=0 to make the system proceed it did a: 24-Nov 16:18 bacula-sd JobId 20268: 3301 Issuing autochanger "loaded? drive 0" command. 24-Nov 16:18 bacula-sd JobId 20268: 3302 Autochanger "loaded? drive 0", result: nothing loaded. 24-Nov 16:18 bacula-sd JobId 20268: 3304 Issuing autochanger "load slot 92, drive 0" command. 24-Nov 16:19 bacula-sd JobId 20268: 3305 Autochanger "load slot 92, drive 0", status is OK. 24-Nov 16:19 bacula-sd JobId 20268: 3307 Issuing autochanger "unload slot 92, drive 0" command. 24-Nov 16:20 bacula-sd JobId 20268: Warning: acquire.c:260 Wrong Volume mounted on device "LTO3-0" (/dev/nst0): Wanted 00072 3L3 have 000788L3 24-Nov 16:20 bacula-sd JobId 20268: Please mount Volume "000723L3" for: Job: RestoreFiles.2008-11-24_15.37.01 Storage: "LTO3-0" (/dev/nst0) Pool: Full-Pool Media type: LTO3 slot 92 was the "old" slotnumber for the volume. Even doing a sqlquery: update Media set slot=0, inChanger = 0 and a subsequence update slots made bacula load slot 92 once more. Consulting the catalog it showed correctly slot=132 inchanger=1 for the neede volume. ====================================================================== ---------------------------------------------------------------------- (0003794) Dan Langille (manager) - 2008-11-26 02:33 http://bugs.bacula.org/view.php?id=1194#c3794 ---------------------------------------------------------------------- Please help us out by attempting to reproduce the problem. ---------------------------------------------------------------------- (0003795) jesperkrogh (reporter) - 2008-11-26 05:22 http://bugs.bacula.org/view.php?id=1194#c3795 ---------------------------------------------------------------------- I'll try to. How do I best capture a trace of the process/states that bacula is in? Is the most optimal way to just do as above: first, then .. and so? ---------------------------------------------------------------------- (0003796) Dan Langille (manager) - 2008-11-26 10:46 http://bugs.bacula.org/view.php?id=1194#c3796 ---------------------------------------------------------------------- I wouldn't bother with a trace first. I'd start by reproducing the problem, and providing us with the steps involved. ---------------------------------------------------------------------- (0003821) jesperkrogh (reporter) - 2008-12-09 12:12 http://bugs.bacula.org/view.php?id=1194#c3821 ---------------------------------------------------------------------- Sorry for the delay. Here's a complete trace. I have a tape with this information in the catalog: MediaId: 314 VolumeName: 001682L3 Slot: 17 PoolId: 3 MediaType: LTO3 FirstWritten: 2008-09-14 08:43:45 LastWritten: 2008-09-14 23:27:05 LabelDate: 2008-09-14 08:43:45 VolJobs: 13 VolFiles: 572 VolBlocks: 8,821,294 VolMounts: 2 VolBytes: 569,079,383,040 VolErrors: 0 VolWrites: 8,821,296 VolCapacityBytes: 0 VolStatus: Full Enabled: 1 Recycle: 1 VolRetention: 15,552,000 VolUseDuration: 0 MaxVolJobs: 0 MaxVolFiles: 0 MaxVolBytes: 0 InChanger: 0 EndFile: 571 EndBlock: 14,047 VolParts: 0 LabelType: 0 StorageId: 2 DeviceId: 0 LocationId: 0 RecycleCount: 0 InitialWrite: 0000-00-00 00:00:00 ScratchPoolId: 6 RecyclePoolId: 6 Comment: NULL Note: inChanger = 0, but slot is set to something. jk@bacula:~/adm$ sudo mtx -f /dev/changer status | grep 001682L3 jk@bacula:~/adm$ According to my information this file should recide on the tape: -rw-rw-r-- jk jk 357120716 Sat Sep 13 22:10:48 2008 kat-fd:/tmp/all3.out Go to bconsole and start a restore of that: restore -> 6 -> 2008-09-16 00:00:00 -> kat-fd -> Root Set -> "cd /tmp; mark all3.out" -> done --- prints ---- The job will require the following Volume(s) Storage(s) SD Device(s) =========================================================================== 001682L3 LTO-3 LTO3 --------------- -> yes (to actually run). 09-Dec 09:49 bacula-dir JobId 20710: Start Restore Job RestoreFiles.2008-12-09_09.49.28 09-Dec 09:49 bacula-dir JobId 20710: Using Device "LTO3-0" 09-Dec 09:49 bacula-sd JobId 20710: Invalid slot=0 defined in catalog for Volume "001682L3" on "LTO3-0" (/dev/nst0). Manual load may be required. 09-Dec 09:49 bacula-sd JobId 20710: 3301 Issuing autochanger "loaded? drive 0" command. 09-Dec 09:49 bacula-sd JobId 20710: 3302 Autochanger "loaded? drive 0", result: nothing loaded. 09-Dec 09:49 bacula-sd JobId 20710: Warning: acquire.c:221 Read open device "LTO3-0" (/dev/nst0) Volume "001682L3" failed: ERR=dev.c:432 Unable to open device "LTO3-0" (/dev/nst0): ERR=No medium found 09-Dec 09:49 bacula-sd JobId 20710: 3301 Issuing autochanger "loaded? drive 0" command. 09-Dec 09:49 bacula-sd JobId 20710: 3302 Autochanger "loaded? drive 0", result: nothing loaded. 09-Dec 09:49 bacula-sd JobId 20710: 3304 Issuing autochanger "load slot 17, drive 0" command. ###### Why does it start a "load slot 17" when it actually knows the wrong tape is in the slot. 09-Dec 09:50 bacula-sd JobId 20710: 3305 Autochanger "load slot 17, drive 0", status is OK. 09-Dec 09:50 bacula-sd JobId 20710: 3307 Issuing autochanger "unload slot 17, drive 0" command. 09-Dec 09:51 bacula-sd JobId 20710: Warning: acquire.c:260 Wrong Volume mounted on device "LTO3-0" (/dev/nst0): Wanted 001682L3 have 000866L3 09-Dec 09:51 bacula-sd JobId 20710: Please mount Volume "001682L3" for: Job: RestoreFiles.2008-12-09_09.49.28 Storage: "LTO3-0" (/dev/nst0) Pool: Full-Pool Media type: LTO3 ### OK Fair enough.. As expected it wasn't in the catalog. Now I go insert it. # mtx -f /dev/changer status | grep 1682 Storage Element 133 IMPORT/EXPORT:Full :VolumeTag=001682L3 # /etc/bacula/scripts/mtx-changer /dev/changer list | grep 1682 133:001682L3 Update slots in bconsole (output skipped). Catalog record for Volume "001682L3" updated to reference slot 133. llist on the media: MediaId: 314 VolumeName: 001682L3 Slot: 133 PoolId: 3 MediaType: LTO3 FirstWritten: 2008-09-14 08:43:45 LastWritten: 2008-09-14 23:27:05 LabelDate: 2008-09-14 08:43:45 VolJobs: 13 VolFiles: 572 VolBlocks: 8,821,294 VolMounts: 2 VolBytes: 569,079,383,040 VolErrors: 0 VolWrites: 8,821,296 VolCapacityBytes: 0 VolStatus: Full Enabled: 1 Recycle: 1 VolRetention: 15,552,000 VolUseDuration: 0 MaxVolJobs: 0 MaxVolFiles: 0 MaxVolBytes: 0 InChanger: 1 EndFile: 571 EndBlock: 14,047 VolParts: 0 LabelType: 0 StorageId: 2 DeviceId: 0 LocationId: 0 RecycleCount: 0 InitialWrite: 0000-00-00 00:00:00 ScratchPoolId: 6 RecyclePoolId: 6 Comment: NULL Note slot=133 inchanger=1 Now issue a mount command to the Storage Daemon again. *mount drive=0 Automatically selected Storage: LTO-3 3001 OK mount. Device="LTO3-0" (/dev/nst0) You have messages. *m 09-Dec 13:06 bacula-sd JobId 20710: 3301 Issuing autochanger "loaded? drive 0" command. 09-Dec 13:06 bacula-sd JobId 20710: 3302 Autochanger "loaded? drive 0", result: nothing loaded. 09-Dec 13:06 bacula-sd JobId 20710: 3304 Issuing autochanger "load slot 17, drive 0" command. 09-Dec 13:07 bacula-sd JobId 20710: 3305 Autochanger "load slot 17, drive 0", status is OK. 09-Dec 13:07 bacula-sd JobId 20710: 3307 Issuing autochanger "unload slot 17, drive 0" command. 09-Dec 13:08 bacula-sd JobId 20710: Warning: acquire.c:260 Wrong Volume mounted on device "LTO3-0" (/dev/nst0): Wanted 001682L3 have 000866L3 " (/dev/nst0): Wanted 001682L3 have 000866L3 09-Dec 13:08 bacula-sd JobId 20710: 3301 Issuing autochanger "loaded? drive 0" command. 09-Dec 13:08 bacula-sd JobId 20710: 3302 Autochanger "loaded? drive 0", result: nothing loaded. 09-Dec 13:08 bacula-sd JobId 20710: 3304 Issuing autochanger "load slot 17, drive 0" command. 09-Dec 13:09 bacula-sd JobId 20710: 3305 Autochanger "load slot 17, drive 0", status is OK. 09-Dec 13:09 bacula-sd JobId 20710: 3307 Issuing autochanger "unload slot 17, drive 0" command. 09-Dec 13:10 bacula-sd JobId 20710: Warning: acquire.c:260 Wrong Volume mounted on device "LTO3-0" (/dev/nst0): Wanted 001682L3 have 000866L3 09-Dec 13:10 bacula-sd JobId 20710: Please mount Volume "001682L3" for: Job: RestoreFiles.2008-12-09_09.49.28 Storage: "LTO3-0" (/dev/nst0) Pool: Full-Pool Media type: LTO3 # Loading slot 17 again.. HUH? mount again just load/unloads slot 17 ---------------------------------------------------------------------- (0003822) jesperkrogh (reporter) - 2008-12-09 12:18 http://bugs.bacula.org/view.php?id=1194#c3822 ---------------------------------------------------------------------- The state seems "saved" in the StorageDeamon. Just cancelling the job and starting it over again made the system work correct: Same selections as above.; 09-Dec 13:16 bacula-dir JobId 20711: Start Restore Job RestoreFiles.2008-12-09_13.16.42 09-Dec 13:16 bacula-dir JobId 20711: Using Device "LTO3-0" 09-Dec 13:16 bacula-sd JobId 20711: 3301 Issuing autochanger "loaded? drive 0" command. 09-Dec 13:16 bacula-sd JobId 20711: 3302 Autochanger "loaded? drive 0", result: nothing loaded. 09-Dec 13:16 bacula-sd JobId 20711: 3304 Issuing autochanger "load slot 133, drive 0" command. ---------------------------------------------------------------------- (0003855) kern (administrator) - 2008-12-20 18:27 http://bugs.bacula.org/view.php?id=1194#c3855 ---------------------------------------------------------------------- This looks like normal behavior to me. If the volume is not where it should be, Bacula will ask for operator intervention. You have mentioned several things that you did, which all seem OK, but the key point is that once the problem is corrected, you must manually issue a "mount" command in the console. You did not clearly state whether or not you did this. If you did do the mount, then please show the full console output of all the steps you took following the operator intervention request. ---------------------------------------------------------------------- (0003856) jesperkrogh (reporter) - 2008-12-20 20:07 http://bugs.bacula.org/view.php?id=1194#c3856 ---------------------------------------------------------------------- Sorry if it isn't clear, but above is all the steps including operator intervention steps. All bacula prompts is listed with the * in front of the line. You can find the mount command above by searing for "mount drive=0" . Issue History Date Modified Username Field Change ====================================================================== 2008-11-24 15:55 jesperkrogh New Issue 2008-11-26 02:33 Dan Langille Note Added: 0003794 2008-11-26 05:22 jesperkrogh Note Added: 0003795 2008-11-26 10:46 Dan Langille Note Added: 0003796 2008-12-08 23:25 kshatriyak Issue Monitored: kshatriyak 2008-12-09 12:12 jesperkrogh Note Added: 0003821 2008-12-09 12:18 jesperkrogh Note Added: 0003822 2008-12-11 09:35 ebollengier Severity major => minor 2008-12-20 18:27 kern Note Added: 0003855 2008-12-20 18:27 kern Status new => feedback 2008-12-20 20:07 jesperkrogh Note Added: 0003856 ====================================================================== |