On Friday 31 July 2009, Dustin J. Mitchell wrote:
>On Fri, Jul 31, 2009 at 9:47 AM, Gene Heskett<gene.heskett AT verizon DOT net> 
>wrote:
>> No, 100% PEBKAC.  Somehow the slot9 directory got owned by root, so even
>> if the link 'data' was owned by amanda, amanda had no perms for the target
>> of the link.  I just put the 730 snapshot back in after the flush was
>> done, and it looks like amcheck is happy. I even rebooted to an older
>> kernel before I found that.  Doh!  My bad, I'll take 30 lashes with a wet
>> noodle.  Or can I blame it on ENOCAFFEINE?  I'm a quart low yet this
>> morning.  Gotta fix that, where is my teacup...
>
>Still, it shouldn't have looped forever.  I'd like to see those logs
>all the same.
>
>Dustin

The original taper log is 500 megs!

-rw-r----- 1 amanda amanda 499925942 2009-07-31 08:21 taper.20090731011505.debug

Yes, it should have exited, I agree.  But it was stuck in the look for a 
usable tape loop.

Here is the first 120 lines of it.

1249017305.403261: taper: pid 6099 ruid 500 euid 500 version 2.6.2alpha: start 
at Fri Jul 31 01:15:05 2009                               
1249017305.424744: taper: pid 6099 ruid 500 euid 500 version 2.6.2alpha: rename 
at Fri Jul 31 01:15:05 2009                              
1249017305.446721: taper: Amanda::Changer::compat initialized with script 
/usr/local/libexec/amanda/chg-disk, temporary directory 
/usr/local/etc/amanda/Daily                                                     
                                                                
1249017305.480039: taper: Amanda::Taper::Scan::traditional stage 1: search for 
oldest reusable volume                                    
1249017305.480197: taper: Amanda::Taper::Scan::traditional: oldest reusable 
volume is 'Dailys-9'                                         
1249017305.480340: taper: Amanda::Changer::compat: invoking 
/usr/local/libexec/amanda/chg-disk with -info                                
1249017305.860738: taper: Amanda::Changer::compat: Got response '9 30 1' with 
exit status 0                                              
1249017305.860911: taper: Amanda::Taper::Scan::traditional: changer is not 
fast-searchable; skipping to stage 2                          
1249017305.860925: taper: Amanda::Taper::Scan::traditional stage 2: scan for 
any reusable volume                                         
1249017305.861535: taper: Amanda::Changer::compat: invoking 
/usr/local/libexec/amanda/chg-disk with -slot current                        
1249017306.251529: taper: Amanda::Changer::compat: Got response '9 
file:/amandatapes/Dailys/' with exit status 0                         
1249017306.252656: taper: Amanda::Taper::Scan::traditional: trying slot 9       
                                                         
1249017306.253691: taper: Amanda::Taper::Scan::traditional result: 'Dailys-9' 
on file:/amandatapes/Dailys/, mode 2                       
1249017705.455375: taper: Amanda::Taper::Scribe using split method none         
                                                         
1249017705.501316: taper: Starting <Xfer@0x9faa300 
(<XferSourceHolding@0x9fa9010> -> <XferDestTaper@0x9fc9878>)>                   
      
1249017705.501387: taper: Final linkage: <XferSourceHolding@0x9fa9010> 
-(PULL_BUFFER)-> <XferElementGlue@0x9fcac10> -(PUSH_BUFFER)-> 
<XferDestTaper@0x9fc9878>                                                       
                                                             
1249017705.517209: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00000.Dailys-9: Permission denied                    
      
1249017705.521799: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00007.coyote._opt.0: Permission denied               
      
1249017705.521822: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00013.coyote._home.0: Permission denied              
      
1249017705.521842: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00001.coyote._usr_dlds.0: Permission denied          
      
1249017705.521859: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00012.coyote._usr_bin.1: Permission denied           
      
1249017705.521895: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00017.coyote._usr_sbin.0: Permission denied          
      
1249017705.521914: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00029.coyote._usr_dlds_rpms.1: Permission denied     
      
1249017705.521935: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00008.coyote._root.2: Permission denied              
      
1249017705.521957: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00031.coyote._boot.1: Permission denied              
      
1249017705.521975: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00023.coyote._usr_dlds_misc.1: Permission denied     
      
1249017705.521999: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00006.coyote._GenesAmandaHelper-0.6.0: Permission 
denied   
1249017705.522018: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00026.coyote._sbin.1: Permission denied              
      
1249017705.522053: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00004.coyote._usr_java.0: Permission denied          
      
1249017705.522071: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00019.coyote._usr_libexec.1: Permission denied       
      
1249017705.522089: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00010.coyote._var.0: Permission denied               
      
1249017705.522110: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00024.coyote._usr_dlds_tgzs.1: Permission denied     
      
1249017705.522130: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00030.coyote._bin.1: Permission denied               
      
1249017705.522150: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00005.coyote._usr_pix.1: Permission denied           
      
1249017705.522191: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00009.coyote._usr_weber.0: Permission denied         
      
1249017705.522207: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00003.coyote._usr_dlds.0: Permission denied          
      
1249017705.522238: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00025.coyote._usr_brlcad.1: Permission denied        
      
1249017705.522260: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00028.coyote._usr_music.1: Permission denied         
      
1249017705.522279: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00018.coyote._etc.0: Permission denied               
      
1249017705.522313: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00022.coyote._usr_include.1: Permission denied       
      
1249017705.522331: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00021.coyote._lib.1: Permission denied               
      
1249017705.522348: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00020.coyote._usr_src.1: Permission denied           
      
1249017705.522364: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00014.coyote._usr_local.1: Permission denied         
      
1249017705.522381: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00002.coyote._usr_movies.0: Permission denied        
      
1249017705.522398: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00011.coyote._usr_share.0: Permission denied         
      
1249017705.522418: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00015.coyote._usr_lib.0: Permission denied           
      
1249017705.522452: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00027.coyote._usr_kerberos.1: Permission denied      
      
1249017705.522484: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00016.coyote._tmp.0: Permission denied               
      
1249017705.522557: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00000.Dailys-9                                 
1249017705.522568: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00007.coyote._opt.0                            
1249017705.522577: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00013.coyote._home.0                           
1249017705.522585: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00001.coyote._usr_dlds.0                       
1249017705.522594: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00012.coyote._usr_bin.1                        
1249017705.522602: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00017.coyote._usr_sbin.0                       
1249017705.522611: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00029.coyote._usr_dlds_rpms.1                  
1249017705.522619: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00008.coyote._root.2                           
1249017705.522627: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00031.coyote._boot.1                           
1249017705.522640: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00023.coyote._usr_dlds_misc.1                  
1249017705.522649: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00006.coyote._GenesAmandaHelper-0.6.0          
1249017705.522671: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00026.coyote._sbin.1                           
1249017705.522680: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00004.coyote._usr_java.0                       
1249017705.522688: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00019.coyote._usr_libexec.1                    
1249017705.522696: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00010.coyote._var.0                            
1249017705.522705: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00024.coyote._usr_dlds_tgzs.1                  
1249017705.522713: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00030.coyote._bin.1                            
1249017705.522721: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00005.coyote._usr_pix.1                        
1249017705.522730: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00009.coyote._usr_weber.0                      
1249017705.522738: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00003.coyote._usr_dlds.0                       
1249017705.522747: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00025.coyote._usr_brlcad.1                     
1249017705.522755: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00028.coyote._usr_music.1                      
1249017705.522763: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00018.coyote._etc.0                            
1249017705.522779: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00022.coyote._usr_include.1                    
1249017705.522796: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00021.coyote._lib.1                            
1249017705.522814: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00020.coyote._usr_src.1                        
1249017705.522823: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00014.coyote._usr_local.1                      
1249017705.522833: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00002.coyote._usr_movies.0                     
1249017705.522841: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00011.coyote._usr_share.0                      
1249017705.522849: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00015.coyote._usr_lib.0                        
1249017705.522858: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00027.coyote._usr_kerberos.1                   
1249017705.522867: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00016.coyote._tmp.0                            
1249017705.522898: taper: Device file:/amandatapes/Dailys/ error = 'Can't open 
file /amandatapes/Dailys//data//00000.Dailys-9: File 
exists'                                                                         
                                                              
1249017705.522968: taper: Device file:/amandatapes/Dailys/ setting status 
flag(s): DEVICE_STATUS_DEVICE_ERROR, and 
DEVICE_STATUS_VOLUME_ERROR                                                      
                                                                               
1249017705.681451: taper: Amanda::Taper::Scan::traditional stage 1: search for 
oldest reusable volume
1249017705.681828: taper: Amanda::Taper::Scan::traditional: oldest reusable 
volume is 'Dailys-9'
1249017705.682021: taper: Amanda::Taper::Scan::traditional: changer is not 
fast-searchable; skipping to stage 2
1249017705.682035: taper: Amanda::Taper::Scan::traditional stage 2: scan for 
any reusable volume
1249017705.682871: taper: Amanda::Changer::compat: invoking 
/usr/local/libexec/amanda/chg-disk with -slot current
1249017707.127181: taper: Amanda::Changer::compat: Got response '9 
file:/amandatapes/Dailys/' with exit status 0
1249017707.127999: taper: Amanda::Taper::Scan::traditional: trying slot 9
1249017707.129563: taper: Amanda::Taper::Scan::traditional result: 'Dailys-9' 
on file:/amandatapes/Dailys/, mode 2
1249017707.129761: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00000.Dailys-9: Permission denied
1249017707.129778: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00007.coyote._opt.0: Permission denied
1249017707.129795: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00013.coyote._home.0: Permission denied
1249017707.129809: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00001.coyote._usr_dlds.0: Permission denied
1249017707.129826: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00012.coyote._usr_bin.1: Permission denied
1249017707.129839: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00017.coyote._usr_sbin.0: Permission denied
1249017707.129853: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00029.coyote._usr_dlds_rpms.1: Permission denied
1249017707.129867: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00008.coyote._root.2: Permission denied
1249017707.129881: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00031.coyote._boot.1: Permission denied
1249017707.129895: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00023.coyote._usr_dlds_misc.1: Permission denied
1249017707.129910: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00006.coyote._GenesAmandaHelper-0.6.0: Permission 
denied
1249017707.129924: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00026.coyote._sbin.1: Permission denied
1249017707.129939: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00004.coyote._usr_java.0: Permission denied
1249017707.129955: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00019.coyote._usr_libexec.1: Permission denied
1249017707.129967: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00010.coyote._var.0: Permission denied
1249017707.129981: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00024.coyote._usr_dlds_tgzs.1: Permission denied
1249017707.130016: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00030.coyote._bin.1: Permission denied
1249017707.130034: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00005.coyote._usr_pix.1: Permission denied
1249017707.130050: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00009.coyote._usr_weber.0: Permission denied
1249017707.130067: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00003.coyote._usr_dlds.0: Permission denied
1249017707.130085: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00025.coyote._usr_brlcad.1: Permission denied
1249017707.130098: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00028.coyote._usr_music.1: Permission denied
1249017707.130110: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00018.coyote._etc.0: Permission denied
1249017707.130123: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00022.coyote._usr_include.1: Permission denied
1249017707.130138: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00021.coyote._lib.1: Permission denied
1249017707.130154: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00020.coyote._usr_src.1: Permission denied
1249017707.130167: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00014.coyote._usr_local.1: Permission denied
1249017707.130180: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00002.coyote._usr_movies.0: Permission denied
1249017707.130193: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00011.coyote._usr_share.0: Permission denied
1249017707.130206: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00015.coyote._usr_lib.0: Permission denied

Then looped for another 499 megs worth, the only thing changing was the
timestamp.  Using a decent amount of cpu too, but with a 4 core phenom
I do have some to spare. :)

-- 
Cheers, Gene
"There are four boxes to be used in defense of liberty:
 soap, ballot, jury, and ammo. Please use in that order."
-Ed Howdershelt (Author)