Bacula-users

Re: [Bacula-users] Potential Major problem with 2.4.0 recycling tape.

2008-06-24 17:03:49
Subject: Re: [Bacula-users] Potential Major problem with 2.4.0 recycling tape.
From: Arno Lehmann <al AT its-lehmann DOT de>
To: bacula-users AT lists.sourceforge DOT net
Date: Tue, 24 Jun 2008 22:48:36 +0200
Hi,

24.06.2008 16:12, Stephen Carr wrote:
> Dear All
> 
> Sorry for this - I hope it is a red herring last Saturday I had what I 
> thought was a tape problem and asked about rerunning a migration job.
> 
> Tonight a tape was incorrectly recycled instead of requesting the next 
> tape to be loaded.
> 
> See below.
> 
> Will revert to 2.2.8 in interim.
> 
> Enter MediaId or Volume name: LTO-D1
> Updating Volume "LTO-D1"
> Current retention period is: 28 days
> 
> Can someone test this out on small capacity tape unit 300GB a long way 
> to wait for error.

As we can not reproduce your exact setup this might be difficult (and 
don't talk about the time needed to test...).

But you could set the maximum volume bytes to something lower and see 
for yourself. It might help if you run the DIR and SD with debug 
tracing enabled, too, so you can collect all the information for a 
detailed bug report.

Arno

> I usually change tapes if close to 300 GB event at 250 GB.
> 
> I have also included info from log.
> 
> Regards
> Stephen Carr
> 
> ###################################
> Recycling in error
> ###################################
> 
> 24-Jun 18:30 elizabeth-dir JobId 58648: The following 1 JobIds were 
> chosen to be migrated: 58581
> 24-Jun 18:30 elizabeth-dir JobId 58648: Migration using JobId=58581 
> Job=civengb179.2008-06-24_11.20.52
> 24-Jun 18:30 elizabeth-dir JobId 58648: Storage "" not found, using 
> Storage "File" from MediaType "File".
> 24-Jun 18:30 elizabeth-dir JobId 58648: Bootstrap records written to 
> /common/bacula/elizabeth-dir.restore.41.bsr
> 24-Jun 18:30 elizabeth-dir JobId 58648:
> 24-Jun 18:30 elizabeth-dir JobId 58648: The job will require the following
>     Volume(s)                 Storage(s)                SD Device(s)
> ===========================================================================
> 24-Jun 18:30 elizabeth-dir JobId 58648:
> 24-Jun 18:30 elizabeth-dir JobId 58648:    Full0951 
> 
> 24-Jun 18:30 elizabeth-dir JobId 58648:
> 24-Jun 21:08 elizabeth-dir JobId 58648: Start Migration JobId 58648, 
> Job=Migrate-Full.2008-06-24_18.30.16
> 24-Jun 21:08 elizabeth-dir JobId 58648: Using Device "LTO"
> 24-Jun 21:08 elizabeth-sd JobId 58648: Ready to read from volume 
> "Full0951" on device "File" (/wd1000).
> 24-Jun 21:08 elizabeth-sd JobId 58648: Forward spacing Volume "Full0951" 
> to file:block 0:202.
> 24-Jun 21:42 elizabeth-sd JobId 58648: End of Volume "LTO-D1" at 
> 294:8935 on device "LTO" (/dev/nst1). Write of 64512 bytes got -1.
> 24-Jun 21:42 elizabeth-sd JobId 58648: Re-read of last block succeeded.
> 24-Jun 21:42 elizabeth-sd JobId 58648: End of medium on Volume "LTO-D1" 
> Bytes=273,626,357,760 Blocks=4,241,479 at 24-Jun-2008 21:42.
> 24-Jun 21:43 elizabeth-sd JobId 58648: Recycled volume "LTO-D1" on 
> device "LTO" (/dev/nst1), all previous data lost.
> 24-Jun 21:43 elizabeth-sd JobId 58648: New volume "LTO-D1" mounted on 
> device "LTO" (/dev/nst1) at 24-Jun-2008 21:43.
> 24-Jun 21:43 elizabeth-sd JobId 58648: End of file 8 on device "File" 
> (/wd1000), Volume "Full0951"
> 24-Jun 21:43 elizabeth-sd JobId 58648: End of Volume at file 8 on device 
> "File" (/wd1000), Volume "Full0951"
> 24-Jun 21:43 elizabeth-sd JobId 58648: End of all volumes.
> 24-Jun 21:43 elizabeth-dir JobId 58648: Bacula elizabeth-dir 2.4.0 
> (04Jun08): 24-Jun-2008 21:43:30
>    Build OS:               i686-pc-linux-gnu slackware Slackware 9.1.0
>    Prev Backup JobId:      58581
>    New Backup JobId:       58649
>    Migration JobId:        58648
>    Migration Job:          Migrate-Full.2008-06-24_18.30.16
>    Backup Level:           Full
>    Client:                 elizabeth
>    FileSet:                "workstation" 2006-09-07 16:00:03
>    Read Pool:              "Migrate-Full" (From Job resource)
>    Read Storage:           "File" (From Pool resource)
>    Write Pool:             "Full" (From Job Pool's NextPool resource)
>    Write Storage:          "Ultrium" (From Storage from Pool's NextPool 
> resource)
>    Start time:             24-Jun-2008 21:08:07
>    End time:               24-Jun-2008 21:43:30
>    Elapsed time:           35 mins 23 secs
>    Priority:               22
>    SD Files Written:       19,872
>    SD Bytes Written:       20,651,287,536 (20.65 GB)
>    Rate:                   9727.4 KB/s
>    Volume name(s):         LTO-D1
>    Volume Session Id:      158
>    Volume Session Time:    1214014949
>    Last Volume Bytes:      92,187,648 (92.18 MB)
>    SD Errors:              0
>    SD termination status:  OK
>    Termination:            Migration OK
> 
> 24-Jun 21:43 elizabeth-dir JobId 58648: Begin pruning Jobs.
> 24-Jun 21:43 elizabeth-dir JobId 58648: Pruned 1 Job for client 
> elizabeth from catalog.
> 24-Jun 21:43 elizabeth-dir JobId 58648: Begin pruning Files.
> 24-Jun 21:43 elizabeth-dir JobId 58648: No Files found to prune.
> 24-Jun 21:43 elizabeth-dir JobId 58648: End auto prune.
> 
> ##############################
> Prior job
> ################################
> 
> 24-Jun 18:30 elizabeth-dir JobId 58646: The following 1 JobIds were 
> chosen to be migrated: 58580
> 24-Jun 18:30 elizabeth-dir JobId 58646: Migration using JobId=58580 
> Job=civengb178.2008-06-24_11.20.51
> 24-Jun 18:30 elizabeth-dir JobId 58646: Storage "" not found, using 
> Storage "File" from MediaType "File".
> 24-Jun 18:30 elizabeth-dir JobId 58646: Bootstrap records written to 
> /common/bacula/elizabeth-dir.restore.40.bsr
> 24-Jun 18:30 elizabeth-dir JobId 58646:
> 24-Jun 18:30 elizabeth-dir JobId 58646: The job will require the following
>     Volume(s)                 Storage(s)                SD Device(s)
> ===========================================================================
> 24-Jun 18:30 elizabeth-dir JobId 58646:
> 24-Jun 18:30 elizabeth-dir JobId 58646:    Full0951 
> 
> 24-Jun 18:30 elizabeth-dir JobId 58646:
> 24-Jun 20:41 elizabeth-dir JobId 58646: Start Migration JobId 58646, 
> Job=Migrate-Full.2008-06-24_18.30.14
> 24-Jun 20:41 elizabeth-dir JobId 58646: Using Device "LTO"
> 24-Jun 20:41 elizabeth-sd JobId 58646: Ready to read from volume 
> "Full0951" on device "File" (/wd1000).
> 24-Jun 20:41 elizabeth-sd JobId 58646: Forward spacing Volume "Full0951" 
> to file:block 0:202.
> 24-Jun 21:07 elizabeth-sd JobId 58646: End of file 8 on device "File" 
> (/wd1000), Volume "Full0951"
> 24-Jun 21:07 elizabeth-sd JobId 58646: End of Volume at file 8 on device 
> "File" (/wd1000), Volume "Full0951"
> 24-Jun 21:07 elizabeth-sd JobId 58646: End of all volumes.
> 24-Jun 21:07 elizabeth-dir JobId 58646: Bacula elizabeth-dir 2.4.0 
> (04Jun08): 24-Jun-2008 21:07:55
>    Build OS:               i686-pc-linux-gnu slackware Slackware 9.1.0
>    Prev Backup JobId:      58580
>    New Backup JobId:       58647
>    Migration JobId:        58646
>    Migration Job:          Migrate-Full.2008-06-24_18.30.14
>    Backup Level:           Full
>    Client:                 elizabeth
>    FileSet:                "workstation" 2006-09-07 16:00:03
>    Read Pool:              "Migrate-Full" (From Job resource)
>    Read Storage:           "File" (From Pool resource)
>    Write Pool:             "Full" (From Job Pool's NextPool resource)
>    Write Storage:          "Ultrium" (From Storage from Pool's NextPool 
> resource)
>    Start time:             24-Jun-2008 20:41:47
>    End time:               24-Jun-2008 21:07:55
>    Elapsed time:           26 mins 8 secs
>    Priority:               22
>    SD Files Written:       5,046
>    SD Bytes Written:       3,630,970,128 (3.630 GB)
>    Rate:                   2315.7 KB/s
>    Volume name(s):         LTO-D1
>    Volume Session Id:      157
>    Volume Session Time:    1214014949
>    Last Volume Bytes:      253,051,223,040 (253.0 GB)
>    SD Errors:              0
>    SD termination status:  OK
>    Termination:            Migration OK
> 
> ###################################
> log earlier error - media?? Media replaced
> ###################################
> 21-Jun 11:26 elizabeth-dir JobId 58269:
> 21-Jun 11:26 elizabeth-dir JobId 58269: The job will require the following
> 21-Jun 11:26 elizabeth-dir JobId 58269:
> 21-Jun 11:26 elizabeth-dir JobId 58269:    Full0003 
> Ultrium                   LTO
> 21-Jun 11:26 elizabeth-dir JobId 58269:
> 21-Jun 11:26 elizabeth-dir JobId 58269: Start Migration JobId 58269, 
> Job=Migrate-Full.2008-06-21_11.26.34
> 21-Jun 11:26 elizabeth-dir JobId 58269: Using Device "LTO"
> 21-Jun 11:26 elizabeth-sd JobId 58269: Ready to read from volume 
> "Full0003" on device "File" (/wd1000).
> 21-Jun 11:26 elizabeth-sd JobId 58269: Volume "LTO-D1" previously 
> written, moving to end of data.
> 21-Jun 11:46 elizabeth-sd JobId 58269: Error: Unable to position to end 
> of data on device "LTO" (/dev/nst1): ERR=dev.c:895 ioctl MTEOM error on 
> "LTO" (/dev/nst1). ERR=Input/output error.
> 21-Jun 11:46 elizabeth-sd JobId 58269: Marking Volume "LTO-D1" in Error 
> in Catalog.
> 
> ################################################
> Log recycling tape
> ################################################
> 24-Jun 21:08 elizabeth-dir JobId 58648: Start Migration JobId 58648, 
> Job=Migrate-Full.2008-06-24_18.30.16
> 24-Jun 21:08 elizabeth-dir JobId 58648: Using Device "LTO"
> 24-Jun 21:08 elizabeth-sd JobId 58648: Ready to read from volume 
> "Full0951" on device "File" (/wd1000).
> 24-Jun 21:08 elizabeth-sd JobId 58648: Forward spacing Volume "Full0951" 
> to file:block 0:202.
> 24-Jun 21:42 elizabeth-sd JobId 58648: End of Volume "LTO-D1" at 
> 294:8935 on device "LTO" (/dev/nst1). Write of 64512 bytes got -1.
> 24-Jun 21:42 elizabeth-sd JobId 58648: Re-read of last block succeeded.
> 24-Jun 21:42 elizabeth-sd JobId 58648: End of medium on Volume "LTO-D1" 
> Bytes=273,626,357,760 Blocks=4,241,479 at 24-Jun-2008 21:42.
> 24-Jun 21:43 elizabeth-sd JobId 58648: Recycled volume "LTO-D1" on 
> device "LTO" (/dev/nst1), all previous data lost.
> 24-Jun 21:43 elizabeth-sd JobId 58648: New volume "LTO-D1" mounted on 
> device "LTO" (/dev/nst1) at 24-Jun-2008 21:43.
> 24-Jun 21:43 elizabeth-sd JobId 58648: End of file 8 on device "File" 
> (/wd1000), Volume "Full0951"
> 24-Jun 21:43 elizabeth-sd JobId 58648: End of Volume at file 8 on device 
> "File" (/wd1000), Volume "Full0951"
> 24-Jun 21:43 elizabeth-sd JobId 58648: End of all volumes.
> 24-Jun 21:43 elizabeth-dir JobId 58648: Bacula elizabeth-dir 2.4.0 
> (04Jun08): 24-Jun-2008 21:43:30
> 24-Jun 21:43 elizabeth-dir JobId 58648: Begin pruning Jobs.
> 24-Jun 21:43 elizabeth-dir JobId 58648: Pruned 1 Job for client 
> elizabeth from catalog.
> 24-Jun 21:43 elizabeth-dir JobId 58648: Begin pruning Files.
> 24-Jun 21:43 elizabeth-dir JobId 58648: No Files found to prune.
> 24-Jun 21:43 elizabeth-dir JobId 58648: End auto prune.
> 24-Jun 21:43 elizabeth-dir JobId 58630: Start Migration JobId 58630, 
> Job=Migrate-Full.2008-06-24_18.30.58
> 24-Jun 21:43 elizabeth-dir JobId 58630: Using Device "LTO"
> 24-Jun 21:43 elizabeth-sd JobId 58630: Ready to read from volume 
> "Full0951" on device "File" (/wd1000).
> 24-Jun 21:44 elizabeth-sd JobId 58630: Volume "LTO-D1" previously 
> written, moving to end of data.
> 24-Jun 21:44 elizabeth-sd JobId 58630: Ready to append to end of Volume 
> "LTO-D1" at file=1.
> 24-Jun 21:44 elizabeth-sd JobId 58630: Forward spacing Volume "Full0951" 
> to file:block 0:202.
> 
> 

-- 
Arno Lehmann
IT-Service Lehmann
www.its-lehmann.de

-------------------------------------------------------------------------
Check out the new SourceForge.net Marketplace.
It's the best place to buy or sell services for
just about anything Open Source.
http://sourceforge.net/services/buy/index.php
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users

<Prev in Thread] Current Thread [Next in Thread>