Amanda-Users

amanda-2.6.2alpha-20090730, 1st run

2009-07-31 09:22:27
Subject: amanda-2.6.2alpha-20090730, 1st run
From: Gene Heskett <gene.heskett AT verizon DOT net>
To: amanda-users AT amanda DOT org
Date: Fri, 31 Jul 2009 09:11:52 -0400
Greetings;

Built/installed with no config changes, 1st run with a 1GB smaller spec for
the vtape.

At 7:45 in the morning it is still going, and it is usually finished by around 
2  am.

Asking for an 'amstatus Daily' stops after printing the date, and is now using 
99% of the cpu.  Killable with htop.

/dumps/todays-date-time has about 12 GB of unwritten files in it.

/Amandatapes/Dailys/data is pointed at slot9, and the files from 20090701 are 
still there, which would have been correct after the amcheck Daily run that is 
part of my .newmanda install script.  From that I gather that there has been 
no vdisk access since the amdump run began.

The file dates on /tmp/amanda-dbg are many hours ago, at about 2:47 am.

In /tmp/amanda-dbg/Daily/:
[root@coyote Daily]# ls -l taper.20090731011505.debug
-rw-r----- 1 amanda amanda 485783721 2009-07-31 08:08 taper.20090731011505.debug
[root@coyote Daily]# ls -l taper.20090731011505.debug
-rw-r----- 1 amanda amanda 486086891 2009-07-31 08:08 taper.20090731011505.debug

And growing at about 30k/5 seconds.

And a tail on it shows it stuck in this loop:

1249042204.941281: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00000.Dailys-9: Permission denied                    
      
1249042204.941300: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00007.coyote._opt.0: Permission denied               
      
1249042204.941315: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00013.coyote._home.0: Permission denied              
      
1249042204.941329: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00001.coyote._usr_dlds.0: Permission denied          
      
1249042204.941344: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00012.coyote._usr_bin.1: Permission denied           
      
1249042204.941358: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00017.coyote._usr_sbin.0: Permission denied          
      
1249042204.941371: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00029.coyote._usr_dlds_rpms.1: Permission denied     
      
1249042204.941387: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00008.coyote._root.2: Permission denied              
      
1249042204.941401: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00031.coyote._boot.1: Permission denied              
      
1249042204.941416: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00023.coyote._usr_dlds_misc.1: Permission denied     
      
1249042204.941431: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00006.coyote._GenesAmandaHelper-0.6.0: Permission 
denied   
1249042204.941464: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00026.coyote._sbin.1: Permission denied              
      
1249042204.941478: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00004.coyote._usr_java.0: Permission denied          
      
1249042204.941494: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00019.coyote._usr_libexec.1: Permission denied       
      
1249042204.941507: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00010.coyote._var.0: Permission denied               
      
1249042204.941522: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00024.coyote._usr_dlds_tgzs.1: Permission denied     
      
1249042204.941537: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00030.coyote._bin.1: Permission denied               
      
1249042204.941550: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00005.coyote._usr_pix.1: Permission denied           
      
1249042204.941564: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00009.coyote._usr_weber.0: Permission denied         
      
1249042204.941577: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00003.coyote._usr_dlds.0: Permission denied          
      
1249042204.941593: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00025.coyote._usr_brlcad.1: Permission denied        
      
1249042204.941608: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00028.coyote._usr_music.1: Permission denied         
      
1249042204.941622: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00018.coyote._etc.0: Permission denied               
      
1249042204.941635: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00022.coyote._usr_include.1: Permission denied       
      
1249042204.941648: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00021.coyote._lib.1: Permission denied               
      
1249042204.941661: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00020.coyote._usr_src.1: Permission denied           
      
1249042204.941675: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00014.coyote._usr_local.1: Permission denied         
      
1249042204.941688: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00002.coyote._usr_movies.0: Permission denied        
      
1249042204.941701: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00011.coyote._usr_share.0: Permission denied         
      
1249042204.941714: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00015.coyote._usr_lib.0: Permission denied           
      
1249042204.941728: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00027.coyote._usr_kerberos.1: Permission denied      
      
1249042204.941741: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00016.coyote._tmp.0: Permission denied               
      
1249042204.941805: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00000.Dailys-9                                 
1249042204.941817: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00007.coyote._opt.0                            
1249042204.941826: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00013.coyote._home.0                           
1249042204.941834: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00001.coyote._usr_dlds.0                       
1249042204.941842: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00012.coyote._usr_bin.1                        
1249042204.941850: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00017.coyote._usr_sbin.0                       
1249042204.941869: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00029.coyote._usr_dlds_rpms.1                  
1249042204.941877: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00008.coyote._root.2                           
1249042204.941885: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00031.coyote._boot.1                           
1249042204.941893: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00023.coyote._usr_dlds_misc.1                  
1249042204.941902: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00006.coyote._GenesAmandaHelper-0.6.0          
1249042204.941911: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00026.coyote._sbin.1                           
1249042204.941919: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00004.coyote._usr_java.0                       
1249042204.941935: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00019.coyote._usr_libexec.1                    
1249042204.941943: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00010.coyote._var.0                            
1249042204.941951: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00024.coyote._usr_dlds_tgzs.1                  
1249042204.941960: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00030.coyote._bin.1                            
1249042204.941968: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00005.coyote._usr_pix.1                        
1249042204.941976: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00009.coyote._usr_weber.0                      
1249042204.941984: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00003.coyote._usr_dlds.0                       
1249042204.941992: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00025.coyote._usr_brlcad.1                     
1249042204.942000: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00028.coyote._usr_music.1                      
1249042204.942009: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00018.coyote._etc.0                            
1249042204.942018: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00022.coyote._usr_include.1                    
1249042204.942026: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00021.coyote._lib.1                            
1249042204.942035: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00020.coyote._usr_src.1                        
1249042204.942047: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00014.coyote._usr_local.1                      
1249042204.942055: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00002.coyote._usr_movies.0                     
1249042204.942064: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00011.coyote._usr_share.0                      
1249042204.942072: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00015.coyote._usr_lib.0                        
1249042204.942081: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00027.coyote._usr_kerberos.1                   
1249042204.942091: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00016.coyote._tmp.0                            
1249042204.942120: taper: Device file:/amandatapes/Dailys/ error = 'Can't open 
file /amandatapes/Dailys//data//00000.Dailys-9: File 
exists'                                                                         
                                                              
1249042204.942139: taper: Device file:/amandatapes/Dailys/ setting status 
flag(s): DEVICE_STATUS_DEVICE_ERROR, and 
DEVICE_STATUS_VOLUME_ERROR                                                      
                                                                               
1249042204.943512: taper: Amanda::Taper::Scan::traditional stage 1: search for 
oldest reusable volume                                    
1249042204.943666: taper: Amanda::Taper::Scan::traditional: oldest reusable 
volume is 'Dailys-9'                                         
1249042204.943846: taper: Amanda::Taper::Scan::traditional: changer is not 
fast-searchable; skipping to stage 2                          
1249042204.943859: taper: Amanda::Taper::Scan::traditional stage 2: scan for 
any reusable volume                                         
1249042204.944629: taper: Amanda::Changer::compat: invoking 
/usr/local/libexec/amanda/chg-disk with -slot current                        
1249042205.404065: taper: Amanda::Changer::compat: Got response '9 
file:/amandatapes/Dailys/' with exit status 0                         
1249042205.404884: taper: Amanda::Taper::Scan::traditional: trying slot 9

Ok, permissions, hummm:
[root@coyote Daily]# ls -l /amandatapes/Dailys/data/
total 36385000
-rw------- 1 amanda amanda       32768 2009-07-01 00:15 00000.Dailys-9
-rw------- 1 amanda amanda   786989056 2009-07-01 00:16 00001.coyote._usr_dlds.0
-rw------- 1 amanda amanda 11469611008 2009-07-01 00:35 
00002.coyote._usr_movies.0
-rw------- 1 amanda amanda  3770165248 2009-07-01 00:36 00003.coyote._usr_dlds.0
-rw------- 1 amanda amanda   207495168 2009-07-01 00:37 00004.coyote._usr_java.0
-rw------- 1 amanda amanda      155648 2009-07-01 00:37 00005.coyote._usr_pix.1
-rw------- 1 amanda amanda  5500972956 2009-07-01 00:53 
00006.coyote._GenesAmandaHelper-0.6.0
-rw------- 1 amanda amanda  6281732286 2009-07-01 01:12 00007.coyote._opt.0
-rw------- 1 amanda amanda  1476591071 2009-07-01 01:16 00008.coyote._root.2
-rw------- 1 amanda amanda   140525568 2009-07-01 01:16 
00009.coyote._usr_weber.0
-rw------- 1 amanda amanda  2204238609 2009-07-01 01:34 00010.coyote._var.0
-rw------- 1 amanda amanda  1947411400 2009-07-01 01:49 
00011.coyote._usr_share.0
-rw------- 1 amanda amanda    22540288 2009-07-01 01:49 00012.coyote._usr_bin.1
-rw------- 1 amanda amanda  2375102226 2009-07-01 02:16 00013.coyote._home.0
-rw------- 1 amanda amanda    27039267 2009-07-01 02:16 
00014.coyote._usr_local.1
-rw------- 1 amanda amanda   694614070 2009-07-01 02:26 00015.coyote._usr_lib.0
-rw------- 1 amanda amanda    10367469 2009-07-01 02:26 00016.coyote._tmp.0
-rw------- 1 amanda amanda    22328814 2009-07-01 02:27 00017.coyote._usr_sbin.0
-rw------- 1 amanda amanda    20292590 2009-07-01 02:27 00018.coyote._etc.0
-rw------- 1 amanda amanda      102284 2009-07-01 02:28 
00019.coyote._usr_libexec.1
-rw------- 1 amanda amanda     3056638 2009-07-01 02:29 00020.coyote._usr_src.1
-rw------- 1 amanda amanda      240232 2009-07-01 02:29 00021.coyote._lib.1
-rw------- 1 amanda amanda      167541 2009-07-01 02:30 
00022.coyote._usr_include.1
-rw------- 1 amanda amanda       73728 2009-07-01 02:30 
00023.coyote._usr_dlds_misc.1
-rw------- 1 amanda amanda       43008 2009-07-01 02:30 
00024.coyote._usr_dlds_tgzs.1
-rw------- 1 amanda amanda      186368 2009-07-01 02:30 
00025.coyote._usr_brlcad.1
-rw------- 1 amanda amanda       43008 2009-07-01 02:31 00026.coyote._sbin.1
-rw------- 1 amanda amanda       53248 2009-07-01 02:31 
00027.coyote._usr_kerberos.1
-rw------- 1 amanda amanda       43008 2009-07-01 02:31 
00028.coyote._usr_music.1
-rw------- 1 amanda amanda       43008 2009-07-01 02:31 
00029.coyote._usr_dlds_rpms.1
-rw------- 1 amanda amanda       43008 2009-07-01 02:32 00030.coyote._bin.1
-rw------- 1 amanda amanda       43008 2009-07-01 02:32 00031.coyote._boot.1
-rw-r--r-- 1 amanda amanda      102400 2009-07-01 02:33 configuration.tar
-rw-r--r-- 1 amanda amanda   259225600 2009-07-01 02:33 indices.tar

Which is exactly like the vtape slot before it and the next one it should use 
tomorrow.

I'm going to kill it, and nuke everything it tried to do if I can find it all.

Humm, would it be salvageable if I deleted them by hand?  I left the 00000 
label file for 10 seconds, no action, then deleted it, at which point the 
data link was reset to the previous slot8, taper could not find a usable tape
and exited, leaving that 12GB sitting in /dumps.

This one failed the Heskett test. :) And I need to relabel slot9.  Or copy 
00000* from slot 8 and edit it.  Ok, got that fixed and it passes amcheck.
Then I re-installed 20090729, amcheck passes fine.  But a flush also fails, 
looks like for the same reason.  Killed it.

I'd set the date string wrong, so reset that, but flush is now stuck in a 
similar loop, from a tail on 
/tmp/amanda-dbg/server/Daily/taper.20090731085355.debug:

1249045132.222764: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00000.Dailys-9: Permission denied
1249045132.222839: taper: warning: Found spurious storage file 
/amandatapes/Dailys//data//00000.Dailys-9
1249045132.222866: taper: Device file:/amandatapes/Dailys/ error = 'Can't open 
file /amandatapes/Dailys//data//00000.Dailys-9: File 
exists'
1249045132.222883: taper: Device file:/amandatapes/Dailys/ setting status 
flag(s): DEVICE_STATUS_DEVICE_ERROR, and 
DEVICE_STATUS_VOLUME_ERROR
1249045132.224104: taper: Amanda::Taper::Scan::traditional stage 1: search for 
oldest reusable volume
1249045132.224231: taper: Amanda::Taper::Scan::traditional: oldest reusable 
volume is 'Dailys-9'
1249045132.224405: taper: Amanda::Taper::Scan::traditional: changer is not 
fast-searchable; skipping to stage 2
1249045132.224419: taper: Amanda::Taper::Scan::traditional stage 2: scan for 
any reusable volume
1249045132.225118: taper: Amanda::Changer::compat: invoking 
/usr/local/libexec/amanda/chg-disk with -slot current
1249045132.622604: taper: Amanda::Changer::compat: Got response '9 
file:/amandatapes/Dailys/' with exit status 0
1249045132.623400: taper: Amanda::Taper::Scan::traditional: trying slot 9
1249045132.624056: taper: Amanda::Taper::Scan::traditional result: 'Dailys-9' 
on file:/amandatapes/Dailys/, mode 2
1249045132.624198: taper: warning: Error unlinking 
/amandatapes/Dailys//data//00000.Dailys-9: Permission denied

selinux is not running here.

I think there should be enough to define the problem here, so I'm not going to
back up another version and repeat, as the version I just re-installed, worked
just fine last night but now fails.  And the dump is still sitting in the
holding disk area.

Your turn. :)

-- 
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)
The NRA is offering FREE Associate memberships to anyone who wants them.
<https://www.nrahq.org/nrabonus/accept-membership.asp>

Another name for a Windows tutorial is "crash course".


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