Hello, Thanks for the detailed info, and from examining the "llist volume...", I believe that I have found what is causing your problems.
A bit of background: as I mentioned, Bacula has been evolving and improving concerning autochangers. For example in 1.38, Bacula could handle multidrive autochangers but not two or more autochangers -- all the Volumes were in *all* the autochangers. Not too good. In 2.0.x, Bacula started keeping track of what Autochanger contains each Volume. It does this with the Media record field StorageId, which points to a really simplistic Autochanger record. Now if InChanger is set but StorageId is not set, there is going to be a problem, because Bacula doesn't know in which Autochanger the Volume is, so it probably will not be selected as the next appendable volume for your changer. In your listing below, the volume 000046L1: (before start of jobs) has StorageId 0 (also after the job, which is surprising). Which means that a request to find the next appendable volume is not going to work for that volume. A specific request to load that Slot will work. Now, exactly how Bacula figured out how to load it, I am not sure (it has several last resort algorthms, one of which probably succeeded). So bottom line: you need to figure out why your Volume has StorageId=0. This is probably because you either you created it with a pre-2.0 Bacula, which didn't know anything about StorageId, or you haven't yet done an "update slots" on your Autochanger, which *should* immediately fix the problem. The morale of the story is in version 2.0 or later of Bacula, it is *critical* to do an "update slots" when moving up from any prior version, and whenever you modify the contents of the magazine. Users who have the habit of manually tweaking the fields in the database such as InChanger, may also have problems. There may be some other "bug" (i.e. sequence of commands such as Scratch pools, or recycling, ...) that cause the StorageId to be lost, so I would suggest you first do an "update slots ..." then check that the StorageId is properly set on all your autochanger volumes, then when you have problems, check again. I believe this (need for update slots) was documented in the 2.0 Release notes, but I can see that it is more important than I thought and I will make sure it is appropriately documented in the manual. Best regards, Kern PS: for non-autochanger configurations, I have noticed that Bacula can label a volume and will often set InChanger=1, which is incorrect, and could lead to the same problem noted above (message: no appendable volume found, ...). In non-autochanger configurations, the StorageId is not significant since the volume can be mounted on any device with the same Media Type. On Thursday 24 May 2007 10:40, Andreas Helmcke wrote: > On 21.05.2007 23:39, Andreas Helmcke wrote: > > Kern Sibbald wrote: > >> On Sunday 20 May 2007 20:33, Andreas Helmcke wrote: > >>> Kern Sibbald wrote: > >>>> Unless I am mistaken, this sounds like a standard support problem rather than > >>>> something specific with Beta version 2.1.10, and as such, you should report > >>>> this on the bacula-users list where you are more likely to get a response. > >>> The reason, why i do think that it is a 2.1.10 specific problem is, that with > >>> version 2.0.3 in the same configuration bacula always finds an appendable > >>> volume for each job and does change the tapes accordingly. > >>> *This* error only happens with version 2.1.10. > >>> > >>> In version 2.0.3 bacula sometimes changes tapes to often, as i already > >>> reported to the bacula-users list. > >> Well, it would have been helpful if you mentioned these points in the > >> beginning. > >> > >> From everything I see, this is most likely not a bug, and if it is a bug, it > >> is probably one that is in 2.0.3 as well. (please note: I said "most likely > >> not" and "probably"). > >> > >> It appears to me that the volume that job 3 wanted was perhaps not purged at > >> the time that job 3 started, because when you finally got it to work, the > >> first thing the SD did was recycle the volume. Since there is no indication > >> when the volume was purged or marked purged, I can only assume it was after > >> job 3 had started, and instead of cancelling it, you probably could have > >> simply done a "mount" and it would have accomplished the same thing. > >> > > Ok. Next try to get nearer to the problem, which might be a bug: > > A few times the backup worked like expected. All of my jobs where > incremental backups which where using already loaded, appendable > volumes. And thy did. No tape swapping (as i have seen Version 2.03 > doing), no errors. > So, as far as i can tell, the volume selection of version 2.1.10 *is* > really improved. > > Now for the problem: > > Briefly: > - SD reports "cannot find any appendable volume" although there is one. > - Nonetheless the job gets started directly after the error message > without further intervention. > > > Starting situation: > - Job in question: Srv01-std (it is the second job of my three jobs, > which will run every day) > - Pool to use volumes from: Srv01-Daily > - The volume, which was used for one of the jobs has reached its "max > use duration". Volume: GLG319L1 > - The list of scheduled jobs shows correctly a new, usable (recycled) > volume for this job. New volume: 000046L1 > - The old (used) volume is still loaded in one drive. > > What happened: > - First job started. Using drive-0 and using the already loaded tape. > - Second job started. This is our "troublemaker" Srv01-std. It is using > drive-1 (OK) but SD reports "cannot find any appendable volume". > Nonetheless it loads the correct volume 000046L1 and runs. > > If have appended some logs and status outputs. > If more logs, configfiles or other information is needed please tell me > and I am very happy to provide it. > Especially if I should run sd and/or dir with debug output, please tell > me which debuglevel would be most helpful. > I just don't like to spoil a mailinglist with data, which no one needs > and which doesn't help to find the bug. > > > Andreas > > > > > Logs, messages and further information: > > status dir: (before start of jobs) > > *elablnsrv04-dir Version: 2.1.10 (18 May 2007) i686-pc-linux-gnu suse 10.0 > > Daemon started 19-May-07 19:15, 62 Jobs run since started. > > Heap: heap=1,507,328 smbytes=62,655 max_bytes=156,442 bufs=378 max_bufs=989 > > > > Scheduled Jobs: > > Level Type Pri Scheduled Name Volume > > =================================================================================== > > Incremental Backup 10 23-May-07 22:05 Srv04-std GLG316L1 > > Incremental Backup 10 23-May-07 22:06 Srv01-std 000046L1 > > Incremental Backup 10 23-May-07 22:07 Mail01-std 000035L1 > > Full Backup 20 23-May-07 22:30 BackupCatalog GLG316L1 > > ==== > > > > status storage=ADIC: (before start of jobs) > > *Connecting to Storage daemon ADIC at elablnsrv04:9103 > > > > elablnsrv04-sd Version: 2.1.10 (18 May 2007) i686-pc-linux-gnu suse 10.0 > > Daemon started 20-May-07 22:40, 18 Jobs run since started. > > Heap: heap=753,664 smbytes=167,946 max_bytes=613,175 bufs=135 max_bufs=262 > > > > Running Jobs: > > No Jobs running. > > ==== > > > > Jobs waiting to reserve a drive: > > ==== > > > > Terminated Jobs: > > JobId Level Files Bytes Status Finished Name > > =================================================================== > > 598 Incr 8,099 546.6 M OK 21-May-07 16:38 Mail01-std > > 596 Incr 225 216.4 M OK 21-May-07 16:41 Srv04-std > > 601 Incr 2,565 467.0 M OK 21-May-07 22:08 Mail01-std > > 600 Incr 2,391 1.578 G OK 21-May-07 22:11 Srv01-std > > 599 Incr 20,697 6.727 G OK 21-May-07 22:17 Srv04-std > > 602 Full 1 2.055 G OK 21-May-07 22:35 BackupCatalog > > 604 Incr 6,567 2.499 G OK 22-May-07 22:11 Srv01-std > > 603 Incr 20,662 6.720 G OK 22-May-07 22:17 Srv04-std > > 605 Incr 74,393 1.445 G OK 22-May-07 22:19 Mail01-std > > 606 Full 1 2.069 G OK 22-May-07 22:35 BackupCatalog > > ==== > > > > Device status: > > Autochanger "ADIC" with devices: > > "Drive-0" (/dev/nst0) > > "Drive-1" (/dev/nst1) > > "Drive-2" (/dev/nst2) > > "Drive-3" (/dev/nst3) > > Device "FileStorage" (/tmp) is not open. > > Device "Drive-0" (/dev/nst0) is mounted with Volume="GLG316L1" Pool="Srv04-Daily" > > Slot 5 is loaded in drive 0. > > Total Bytes=20,680,031,232 Blocks=320,560 Bytes/block=64,512 > > Positioned at File=29 Block=0 > > Device "Drive-1" (/dev/nst1) is mounted with Volume="GLG319L1" Pool="Srv01-Daily" > > Slot 29 is loaded in drive 1. > > Total Bytes=11,934,203,904 Blocks=184,991 Bytes/block=64,512 > > Positioned at File=22 Block=0 > > Device "Drive-2" (/dev/nst2) is mounted with Volume="000035L1" Pool="Mail01-Daily" > > Slot 17 is loaded in drive 2. > > Total Bytes=3,629,703,168 Blocks=56,263 Bytes/block=64,513 > > Positioned at File=6 Block=0 > > Device "Drive-3" (/dev/nst3) is not open. > > Drive 3 status unknown. > > ==== > > > > In Use Volume status: > > ==== > > list volumes pool=Srv01-Daily: (before start of jobs) > > Pool: Srv01-Daily > > +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ > > | MediaId | VolumeName | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten | > > +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ > > | 30 | 000046L1 | Recycle | 1 | 1 | 0 | > > 518,400 | 1 | 43 | 1 | LTO-1 | 2007-05-08 22:24:57 | > > | 37 | 000001L1 | Purged | 1 | 25,290,510,336 | 33 | > > 518,400 | 1 | 37 | 1 | LTO-1 | 2007-05-13 22:26:15 | > > | 59 | GLG324L1 | Used | 1 | 3,253,146,624 | 5 | > > 518,400 | 1 | 35 | 1 | LTO-1 | 2007-05-20 22:14:00 | > > | 61 | GLG319L1 | Used | 1 | 11,934,203,904 | 22 | > > 518,400 | 1 | 29 | 1 | LTO-1 | 2007-05-22 22:11:53 | > > +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ > > > llist volume=GLG319L1: (before start of jobs) > > * MediaId: 61 > > VolumeName: GLG319L1 > > Slot: 29 > > PoolId: 6 > > MediaType: LTO-1 > > FirstWritten: 2007-05-16 22:10:04 > > LastWritten: 2007-05-22 22:11:53 > > LabelDate: 2007-05-16 22:10:04 > > VolJobs: 14 > > VolFiles: 22 > > VolBlocks: 184,991 > > VolMounts: 11 > > VolBytes: 11,934,203,904 > > VolErrors: 0 > > VolWrites: 358,913 > > VolCapacityBytes: 0 > > VolStatus: Used > > Enabled: 1 > > Recycle: 1 > > VolRetention: 518,400 > > VolUseDuration: 518,400 > > MaxVolJobs: 0 > > MaxVolFiles: 0 > > MaxVolBytes: 0 > > InChanger: 1 > > EndFile: 21 > > EndBlock: 7,776 > > VolParts: 0 > > LabelType: 0 > > StorageId: 0 > > DeviceId: 0 > > LocationId: 0 > > RecycleCount: 2 > > InitialWrite: 0000-00-00 00:00:00 > > ScratchPoolId: 0 > > RecyclePoolId: 0 > > Comment: NULL > > > > llist volume=000046L1: (before start of jobs) > > * MediaId: 30 > > VolumeName: 000046L1 > > Slot: 43 > > PoolId: 6 > > MediaType: LTO-1 > > FirstWritten: 1970-01-01 01:00:00 > > LastWritten: 2007-05-08 22:24:57 > > LabelDate: 2007-04-10 04:00:02 > > VolJobs: 0 > > VolFiles: 0 > > VolBlocks: 0 > > VolMounts: 21 > > VolBytes: 1 > > VolErrors: 0 > > VolWrites: 3,002,362 > > VolCapacityBytes: 0 > > VolStatus: Recycle > > Enabled: 1 > > Recycle: 1 > > VolRetention: 518,400 > > VolUseDuration: 518,400 > > MaxVolJobs: 0 > > MaxVolFiles: 0 > > MaxVolBytes: 0 > > InChanger: 1 > > EndFile: 32 > > EndBlock: 13,078 > > VolParts: 0 > > LabelType: 0 > > StorageId: 0 > > DeviceId: 0 > > LocationId: 0 > > RecycleCount: 1 > > InitialWrite: 0000-00-00 00:00:00 > > ScratchPoolId: 0 > > RecyclePoolId: 0 > > Comment: NULL > > > > Job-Log of job Srv01-Std: > > > 23-May 22:06 elablnsrv04-dir: Start Backup JobId 608, Job=Srv01-std.2007-05-23_22.06.00 > > 23-May 22:06 elablnsrv04-dir: Using Device "Drive-1" > > 23-May 22:06 elablnsrv04-sd: Job Srv01-std.2007-05-23_22.06.00 waiting. Cannot find any appendable volumes. > > Please use the "label" command to create a new Volume for: > > Storage: "Drive-1" (/dev/nst1) > > Pool: Srv01-Daily > > Media type: LTO-1 > > 23-May 23:06 elablnsrv04-sd: 3307 Issuing autochanger "unload slot 29, drive 1" command. > > 23-May 23:07 elablnsrv04-sd: 3304 Issuing autochanger "load slot 43, drive 1" command. > > 23-May 23:08 elablnsrv04-sd: 3305 Autochanger "load slot 43, drive 1", status is OK. > > 23-May 23:08 elablnsrv04-sd: 3301 Issuing autochanger "loaded? drive 1" command. > > 23-May 23:08 elablnsrv04-sd: 3302 Autochanger "loaded? drive 1", result is Slot 43. > > 23-May 23:08 elablnsrv04-sd: Recycled volume "000046L1" on device "Drive-1" (/dev/nst1), all previous data lost. > > elablnsrv01-fd: Filesystem change prohibited. Will not descend into /tmp > > elablnsrv01-fd: Filesystem change prohibited. Will not descend into /var > > elablnsrv01-fd: Filesystem change prohibited. Will not descend into /boot > > elablnsrv01-fd: Filesystem change prohibited. Will not descend into /proc > > elablnsrv01-fd: Filesystem change prohibited. Will not descend into /raid > > 23-May 23:18 elablnsrv04-sd: Job write elapsed time = 00:09:48, Transfer rate = 4.077 M bytes/second > > 23-May 23:18 elablnsrv04-dir: Bacula elablnsrv04-dir 2.1.10 (18May07): 23-May-2007 23:18:22 > > Build OS: i686-pc-linux-gnu suse 10.0 > > JobId: 608 > > Job: Srv01-std.2007-05-23_22.06.00 > > Backup Level: Incremental, since=2007-05-22 22:06:03 > > Client: "elablnsrv01-fd" i686-suse-linux-gnu,suse,9.0 > > FileSet: "Srv01-std" 2007-01-17 17:54:01 > > Pool: "Srv01-Daily" (From Job resource) > > Storage: "ADIC" (From Job resource) > > Scheduled time: 23-May-2007 22:06:00 > > Start time: 23-May-2007 22:06:03 > > End time: 23-May-2007 23:18:22 > > Elapsed time: 1 hour 12 mins 19 secs > > Priority: 10 > > FD Files Written: 4,527 > > SD Files Written: 4,527 > > FD Bytes Written: 2,397,014,421 (2.397 GB) > > SD Bytes Written: 2,397,761,826 (2.397 GB) > > Rate: 552.4 KB/s > > Software Compression: None > > VSS: no > > Encryption: no > > Volume name(s): 000046L1 > > Volume Session Id: 20 > > Volume Session Time: 1179693637 > > Last Volume Bytes: 2,399,781,888 (2.399 GB) > > Non-fatal FD errors: 0 > > SD Errors: 0 > > FD termination status: OK > > SD termination status: OK > > Termination: Backup OK > > > > 23-May 23:18 elablnsrv04-dir: Begin pruning Jobs. > > 23-May 23:18 elablnsrv04-dir: No Jobs found to prune. > > 23-May 23:18 elablnsrv04-dir: Begin pruning Files. > > 23-May 23:18 elablnsrv04-dir: No Files found to prune. > > 23-May 23:18 elablnsrv04-dir: End auto prune. > > > > status dir: (after running the jobs) > > > *elablnsrv04-dir Version: 2.1.10 (18 May 2007) i686-pc-linux-gnu suse 10.0 > > Daemon started 19-May-07 19:15, 68 Jobs run since started. > > Heap: heap=1,507,328 smbytes=58,796 max_bytes=156,442 bufs=370 max_bufs=989 > > > > Scheduled Jobs: > > Level Type Pri Scheduled Name Volume > > =================================================================================== > > Incremental Backup 10 24-May-07 22:05 Srv04-std GLG316L1 > > Incremental Backup 10 24-May-07 22:06 Srv01-std 000046L1 > > Incremental Backup 10 24-May-07 22:07 Mail01-std 000035L1 > > Full Backup 20 24-May-07 22:30 BackupCatalog GLG316L1 > > ==== > > > > Running Jobs: > > No Jobs running. > > ==== > > > > Terminated Jobs: > > JobId Level Files Bytes Status Finished Name > > ==================================================================== > > 599 Incr 20,697 6.724 G OK 21-May-07 22:17 Srv04-std > > 602 Full 1 2.055 G OK 21-May-07 22:35 BackupCatalog > > 604 Incr 6,567 2.498 G OK 22-May-07 22:12 Srv01-std > > 603 Incr 20,662 6.717 G OK 22-May-07 22:17 Srv04-std > > 605 Incr 74,393 1.432 G OK 22-May-07 22:19 Mail01-std > > 606 Full 1 2.069 G OK 22-May-07 22:35 BackupCatalog > > 609 Incr 19,486 1.132 G OK 23-May-07 22:16 Mail01-std > > 607 Incr 20,856 6.814 G OK 23-May-07 22:17 Srv04-std > > 608 Incr 4,527 2.397 G OK 23-May-07 23:18 Srv01-std > > 610 Full 1 2.074 G OK 23-May-07 23:24 BackupCatalog > > > > > list volumes pool=Srv01-Daily: (after running the jobs) > > > Pool: Srv01-Daily > > +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ > > | MediaId | VolumeName | VolStatus | Enabled | VolBytes | VolFiles | VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten | > > +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ > > | 30 | 000046L1 | Append | 1 | 2,399,781,888 | 3 | > > 518,400 | 1 | 43 | 1 | LTO-1 | 2007-05-23 23:18:20 | > > | 37 | 000001L1 | Purged | 1 | 25,290,510,336 | 33 | > > 518,400 | 1 | 37 | 1 | LTO-1 | 2007-05-13 22:26:15 | > > | 59 | GLG324L1 | Used | 1 | 3,253,146,624 | 5 | > > 518,400 | 1 | 35 | 1 | LTO-1 | 2007-05-20 22:14:00 | > > | 61 | GLG319L1 | Used | 1 | 11,934,203,904 | 22 | > > 518,400 | 1 | 29 | 1 | LTO-1 | 2007-05-22 22:11:53 | > > +---------+------------+-----------+---------+----------------+----------+--------------+---------+------+-----------+-----------+---------------------+ > > llist volume=000046L1: (after running the jobs) > > > * MediaId: 30 > > VolumeName: 000046L1 > > Slot: 43 > > PoolId: 6 > > MediaType: LTO-1 > > FirstWritten: 2007-05-23 22:06:03 > > LastWritten: 2007-05-23 23:18:20 > > LabelDate: 2007-05-23 22:06:03 > > VolJobs: 1 > > VolFiles: 3 > > VolBlocks: 37,198 > > VolMounts: 22 > > VolBytes: 2,399,781,888 > > VolErrors: 0 > > VolWrites: 3,039,561 > > VolCapacityBytes: 0 > > VolStatus: Append > > Enabled: 1 > > Recycle: 1 > > VolRetention: 518,400 > > VolUseDuration: 518,400 > > MaxVolJobs: 0 > > MaxVolFiles: 0 > > MaxVolBytes: 0 > > InChanger: 1 > > EndFile: 2 > > EndBlock: 6,198 > > VolParts: 0 > > LabelType: 0 > > StorageId: 0 > > DeviceId: 0 > > LocationId: 0 > > RecycleCount: 1 > > InitialWrite: 0000-00-00 00:00:00 > > ScratchPoolId: 0 > > RecyclePoolId: 0 > > Comment: NULL > > > > > > ------------------------------------------------------------------------- > This SF.net email is sponsored by DB2 Express > Download DB2 Express C - the FREE version of DB2 express and take > control of your XML. No limits. Just data. Click to get it now. > http://sourceforge.net/powerbar/db2/ > _______________________________________________ > Bacula-devel mailing list > [EMAIL PROTECTED] > https://lists.sourceforge.net/lists/listinfo/bacula-devel > ------------------------------------------------------------------------- This SF.net email is sponsored by DB2 Express Download DB2 Express C - the FREE version of DB2 express and take control of your XML. No limits. Just data. Click to get it now. http://sourceforge.net/powerbar/db2/ _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
