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.
I've noticed this before because it occassionally shows up in the regression tests. However, since it appears to be a "spurious" or slighly incorrect message that does very little harm other than create a bit of temporary confusion, I haven't placed it very high on the list of 2.1.x oddities to resolve. >From what you describe below, it looks like the SD is complaining about the Volume currently in the drive (not very precisely though) and then proceeds to find a correct volume. Does what I say above seem to more or less describe the problem? If so, it narrows down the possibilities a lot (thanks), and I should be able to find some way to suppress the unwanted message ... Regards, Kern > > > 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
