On Tuesday 05 April 2005 13:02, Arno Lehmann wrote: > Hi. > > I've noticed something, purely accidential. > > Todays backups did the following (among other things): > A job was started which required media from pool Full, media type DDS2. > In the pool I had one volume in status append, one in status purged. > > The job started normally and ran as expected. > > > 05-Apr 08:20 goblin-dir: Start Backup JobId 1667, > > Job=Ork.2005-04-05_08.20.00 05-Apr 08:20 goblin-sd: > > Ork.2005-04-05_08.20.00 Warning: Director wanted Volume "DAT-120-0018". > > Current Volume "DAT-090-0002" not acceptable because: > > 1998 Volume "DAT-090-0002" status is Append, not in Pool. > > 05-Apr 08:20 goblin-sd: Please mount Volume "DAT-120-0018" on Storage > > Device "Sun" for Job Ork.2005-04-05_08.20.00 05-Apr 08:30 goblin-sd: > > Volume "DAT-120-0018" previously written, moving to end of data. 05-Apr > > 08:32 goblin-sd: Ready to append to end of Volume "DAT-120-0018" at > > file=3. 05-Apr 08:32 goblin-sd: Spooling data ... > > 05-Apr 09:02 goblin-sd: User specified spool size reached. > > 05-Apr 09:02 goblin-sd: Writing spooled data to Volume. Despooling > > 1,073,743,771 bytes ... 05-Apr 09:32 goblin-sd: End of Volume > > "DAT-120-0018" at 3:14390 on device /dev/nst2. Write of 64512 bytes got > > -1. 05-Apr 09:33 goblin-sd: Re-read of last block succeeded. > > 05-Apr 09:33 goblin-sd: End of medium on Volume "DAT-120-0018" > > Bytes=2,958,133,844 Blocks=45,855 at 05-Apr-2005 09:33. 05-Apr 09:34 > > goblin-dir: Recycled volume "DAT-120-0019" > > 05-Apr 09:34 goblin-sd: Please mount Volume "DAT-120-0019" on Storage > > Device "Sun" for Job Ork.2005-04-05_08.20.00 > > Then, the volume was full and bacula requested the next volume. I > > changed the tapes and bacula continued: > > 05-Apr 09:36 goblin-sd: Recycled volume "DAT-120-0019" on device > > "/dev/nst2", all previous data lost. 05-Apr 09:36 goblin-sd: New volume > > "DAT-120-0019" mounted on device /dev/nst2 at 05-Apr-2005 09:36. 05-Apr > > 09:44 goblin-sd: Spooling data again ... > > 05-Apr 10:18 goblin-sd: User specified spool size reached. > > 05-Apr 10:18 goblin-sd: Writing spooled data to Volume. Despooling > > 1,073,743,689 bytes ... 05-Apr 11:10 goblin-sd: Spooling data again ... > > 05-Apr 11:40 goblin-sd: User specified spool size reached. > > 05-Apr 11:40 goblin-sd: Writing spooled data to Volume. Despooling > > 1,073,743,636 bytes ... 05-Apr 12:21 goblin-sd: Spooling data again ... > > 05-Apr 12:23 goblin-sd: Committing spooled data to Volume. Despooling > > 85,836,360 bytes ... 05-Apr 12:25 goblin-sd: Sending spooled attrs to the > > Director. Despooling 49,818,542 bytes ... 05-Apr 12:39 goblin-dir: Bacula > > 1.36.2 (28Feb05): 05-Apr-2005 12:39:29 > > So far, nothing unusual, I'd say. Probably I'm overlooking something, > because the funny thing are the following information messages: > > Subject: Bacula: *none* *none* of *none* *none* > Sender: [EMAIL PROTECTED] > To: [EMAIL PROTECTED] > Date: Tue, 05 Apr 2005 09:44:12 +0200 > Message-Id: <[EMAIL PROTECTED]> > > 05-Apr 09:38 goblin-dir: There are no Jobs associated with Volume > "DAT-120-0019". Marking it purged. > > and > > Subject: Bacula: *none* *none* of *none* *none* > Sender: [EMAIL PROTECTED] > To: [EMAIL PROTECTED] > Date: Tue, 05 Apr 2005 12:39:30 +0200 > Message-Id: <[EMAIL PROTECTED]> > > 05-Apr 09:52 goblin-dir: Recycled volume "DAT-120-0019" > > For me, this looks like bacula went through the recycling process of the > tape while it was in use. I have a bad feeling with this.
I suspect that it is more likely that the messages got stuck and that the time/dates are not accurate. See below. > > When I read the job report mail, I'd think that there should be 4 files > on DAT-120-0019: "carry over" from the previous volume, and three times No, it does not work that way. Files (EOF marks) are created at the end of a job or every 2 GB (default -- this can be changed). They are not related to spooling/despooling. So, I'm not too surprised to see only three files on the tape. > > despooled data. Output from "list volumes" is: > > +---------+--------------+-----------+----------------+----------+------- > >-------+---------+------+-----------+-----------+---------------------+ > > > > | MediaId | VolumeName | VolStatus | VolBytes | VolFiles | > > | VolRetention | Recycle | Slot | InChanger | MediaType | LastWritten > > | | > > > > +---------+--------------+-----------+----------------+----------+------- > >-------+---------+------+-----------+-----------+---------------------+ > > ... > > > | 27 | DAT-120-0018 | Full | 2,958,133,844 | 3 | > > | 31,104,000 | 1 | 0 | 0 | DDS1 | 2005-04-05 > > | 09:33:16 | 28 | DAT-120-0019 | Append | 2,377,931,297 | 3 | > > | 31,104,000 | 1 | 0 | 0 | DDS1 | 2005-04-05 > > | 12:25:34 | > > ... > > I guess I can prepare for a "number of files mismatch" error the next > time I access that tape. This is not nice, but tapes are cheap... Unlikely. > > What if the irregular recycling hat happend after the job was done? The messages that you saw were daemon messages (why I am not sure) that means that they did not go through the normal message delivery system that attaches a message to a job and puts a correct time/date. Most likely the message was sent and another thread was chewing up all the time so the message was delayed a few minutes and so the time/date are a bit later. > > And finally, an important question: What am I overlooking? > > ... almost forgot: bacula director and sd are version 1.36.2 > > Arno -- Best regards, Kern ------------------------------------------------------- SF email is sponsored by - The IT Product Guide Read honest & candid reviews on hundreds of IT Products from real users. Discover which products truly live up to the hype. Start reading now. http://ads.osdn.com/?ad_id=6595&alloc_id=14396&op=click _______________________________________________ Bacula-users mailing list Bacula-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
