Results 1 to 3 of 3

Thread: Backups successful except for one directory

  1. #1

    Question Backups successful except for one directory

    Hello, all.
    I'm experiencing a problem backing up the /home directory on only one of our servers. We have 15 other Linux servers and 6 Windows servers that all backup successfully.
    Here are the details: The Amanda backup server (named Gemini) is running Ubuntu Hardy 8.04 32bit and the Amanda 2.6.1p2 from the .deb on this site. The problematic client box (named Scorpio) is running CentOS 4.8 32bit and the 2.6.1p2 client .rpm from this site.

    I have several Disk List Entries being backed up on Scorpio. (/etc, /root, /usr/local/apache, et.al.) and they all work flawlessly. However, the backups for /home on this box fail consistently.

    Here's the output from 'amreport':
    Code:
    *** THE DUMPS DID NOT FINISH PROPERLY!
    
    Hostname: gemini
    Org     : ScorpioBackupsSet
    Config  : DailySet2
    Date    : March 1, 2010
    
    These dumps were to tape DailySet2-6.
    The next 2 tapes Amanda expects to use are: DailySet2-7, DailySet2-8.
    STRANGE DUMP SUMMARY:
       scorpio.pmt.org /home lev 1  STRANGE (see below)
    
    
    STATISTICS:
                              Total       Full      Incr.
                            --------   --------   --------
    Estimate Time (hrs:min)    0:00
    Run Time (hrs:min)         0:01
    Dump Time (hrs:min)        0:13       0:07       0:07
    Output Size (meg)        1334.3     1334.3        0.0
    Original Size (meg)      9376.2     8019.1     1357.0
    Avg Compressed Size (%)    22.1       16.6       54.5   (level:#disks ...)
    Filesystems Dumped           14         13          1   (1:1)
    Avg Dump Rate (k/s)      1709.2     3405.7        0.0
    
    Tape Time (hrs:min)        0:01       0:01       0:00
    Tape Size (meg)          1334.3     1334.3        0.0
    Tape Used (%)               6.7        6.7        0.0
    Filesystems Taped            13         13          0
    
    Chunks Taped                 13         13          0
    Avg Tp Write Rate (k/s) 40718.2    40718.2        -- 
    
    USAGE BY TAPE:
      Label             Time      Size      %    Nb    Nc
      DailySet2-6       0:01     1334M    6.7    13    13
    
    
    STRANGE DUMP DETAILS:
    --  scorpio.mydomain.tld /home lev 1 STRANGE
    sendbackup: start [scorpio.mydomain.tld:/home level 1]
    sendbackup: info BACKUP=/bin/tar
    sendbackup: info RECOVER_CMD=/usr/bin/gzip -dc |/bin/tar -xpGf - ...
    sendbackup: info COMPRESS_SUFFIX=.gz
    sendbackup: info end
    ? /bin/tar: ./[user email caused the STRANGE message - nothing to worry about here]: Warning: Cannot stat: No such file or directory
    | Total bytes written: 1422960640 (1.4GiB, 3.5MiB/s)
    sendbackup: size 1389610
    sendbackup: end
    INFO dumper pid-done 11172
    SUCCESS chunker scorpio.mydomain.tld 
    /home 20100301020001 1 [sec 398.257 kb 756921 kps 1900.7] 
    INFO chunker pid-done 11171 
    STATS driver estimate scorpio.mydomain.tld /home 20100301020001 1 [sec 521 nkb 1568197 ckb 827808 kps 1587] 
    PART taper DailySet2-6 14 scorpio.mydomain.tld /home 20100301020001 1/1 1 [sec 26.279571 kb 756920 kps 28802.617465] 
    DONE taper scorpio.mydomain.tld /home 20100301020001 1 1 [sec 26.279571 kb 756920 kps 28802.617465] 
    INFO dumper pid-done 11046 
    INFO taper tape DailySet2-6 kb 2123270 fm 14 [OK] 
    INFO taper pid-done 11045 INFO dumper pid-done 11047 
    INFO dumper pid-done 11048 INFO dumper pid-done 11049 
    FINISH driver date 20100301020001 time 935.586 
    INFO driver pid-done 11044
    \--------
    NOTES:
      planner: Full dump of scorpio.mydomain.tld:/var/lib/mysql promoted from 6 days ahead.
    <SNIP>
    </SNIP>
      planner: Full dump of scorpio.mydomain.tld:/usr/share/ssl promoted from 6 days ahead.
    
    DUMP SUMMARY:
                                           DUMPER STATS               TAPER STATS 
    HOSTNAME     DISK        L ORIG-MB  OUT-MB  COMP%  MMM:SS   KB/s MMM:SS   KB/s
    -------------------------- ------------------------------------- -------------
    scorpio.pmt. /etc        0      19       5   25.7    0:03 1970.6   0:00 491170.5
    scorpio.pmt. /home       1    1357     739   54.5    6:38 1900.7              
    <SNIP></SNIP>
    scorpio.pmt. -spool/cron 0       0       0    --     0:00   29.1   0:00 3147.2
    
    (brought to you by Amanda version 2.6.1p2)
    So I see /home with information under the DUMPER, but absolutely nothing under the TAPER.

    To troubleshoot, I made a separate set of vtapes and a whole other config exclusively for /home on Scorpio and the _exact_ same thing happens. I can see all the date pile up from dumper, get split up by chunker in my holding disk, and start writing to vtape. So everything appears to work UP TO the point that taper starts writing to vtape.

    I will post output of the taper log for the last run for JUST the /home directory in my next post since I'm about to go over the limit for length.

    This had been backing up successfully for several weeks. I know that we as IT folks always hear "I didn't change _anything_ and it just stopped working" and we know that generally doesn't happen but I've queried my whole team and noone can identify any changes they've made on either client OR server (OS updates, network settings, etc.). In the process of troubleshooting, I have removed and reinstalled the RPM package on the client _after_ the problems began. As previously mentioned, I also added a new vtape/config set to try to diagnose before seeking outside help. I've tried several different dumptypes (comp-user-tar, user-tar, nocomp-user, nocomp-user-span) and they all fail backing up /home.

    Is it likely I'm just missing some obvious message in logs or is there somewhere else I should look for further troubleshooting?

    Thanks in advance!

    -Dave E.
    Last edited by Dave; March 1st, 2010 at 02:23 PM.

  2. #2

    Default

    Output from taper log:
    Code:
    mandabackup@gemini:/var/log/amanda/server/DailySet4$ cat taper.20100301151653.debug 
    1267481813.329408: taper: pid 19331 ruid 1004 euid 1004 version 2.6.1p2: start at Mon Mar  1 15:16:53 2010
    1267481813.355672: taper: taper: pid 19331 executable taper version 2.6.1p2                               
    1267481813.361903: taper: pid 19331 ruid 1004 euid 1004 version 2.6.1p2: rename at Mon Mar  1 15:16:53 2010
    1267481813.362378: taper: getcmd: START-TAPER 20100301151653                                               
    1267481813.363754: taper: changer: >> -info                                                                
    1267481813.961463: taper: changer: << EXITSTATUS 0                                                         
    1267481813.961577: taper: changer: << current 16 0 1                                                       
    1267481813.961615: taper: changer_query: changer return was 16 0 1                                         
    1267481813.961664: taper: changer_query: searchable = 1                                                    
    1267481813.961680: taper: changer_find: looking for NULL changer is searchable = 1                         
    1267481813.961699: taper: changer: >> -slot current                                                        
    1267481814.378184: taper: changer: << EXITSTATUS 0                                                         
    1267481814.378266: taper: changer: << 3 file://backups/backups/amanda/vtape/DailySet4                      
    1267481814.396403: taper: changer_label: DailySet4-3 for slot 3                                            
    1267481814.396450: taper: changer: >> -info                                                                
    1267481814.396801: taper: changer: << EXITSTATUS 0                                                         
    1267481814.396859: taper: changer: << current 16 0 1                                                       
    1267481814.396888: taper: changer_query: changer return was 16 0 1                                         
    1267481814.396918: taper: changer_query: searchable = 1                                                    
    1267481814.396947: taper: changer_label: calling changer -label DailySet4-3                                
    1267481814.396966: taper: changer: >> -label DailySet4-3                                                   
    1267481814.397205: taper: changer: << EXITSTATUS 0                                                         
    1267481814.397246: taper: changer: << 3 file://backups/backups/amanda/vtape/DailySet4                      
    1267481814.397379: taper: changer: >> -slot next                                                           
    1267481814.849766: taper: changer: << EXITSTATUS 0                                                         
    1267481814.849840: taper: changer: << 4 file://backups/backups/amanda/vtape/DailySet4                      
    1267481814.859657: taper: changer_label: DailySet4-4 for slot 4                                            
    1267481814.859706: taper: changer: >> -info                                                                
    1267481814.860048: taper: changer: << EXITSTATUS 0                                                         
    1267481814.860100: taper: changer: << current 16 0 1                                                       
    1267481814.860130: taper: changer_query: changer return was 16 0 1                                         
    1267481814.860164: taper: changer_query: searchable = 1                                                    
    1267481814.860185: taper: changer_label: calling changer -label DailySet4-4                                
    1267481814.860203: taper: changer: >> -label DailySet4-4                                                   
    1267481814.860459: taper: changer: << EXITSTATUS 0                                                         
    1267481814.860507: taper: changer: << 4 file://backups/backups/amanda/vtape/DailySet4                      
    1267481814.860815: taper: putresult: 25 TAPER-OK                                                           
    1267482586.302503: taper: getcmd: FILE-WRITE 00-00002 /holding_disk/20100301151653/scorpio.mydomain.tld._home.1 scorpio.mydomain.tld /home 1 20100301151653 2147483648                                                                                              
    1267482586.303351: taper: putresult: 26 REQUEST-NEW-TAPE                                                                     
    1267482586.303572: taper: getcmd: NEW-TAPE                                                                                   
    1267482586.325254: taper: Building type 1 (TAPESTART) header of size 32768 using:                                            
    1267482586.325312: taper: Contents of *(dumpfile_t *)0xb6d0c438:                                                             
    1267482586.325328: taper:     type             = 1 (TAPESTART)                                                               
    1267482586.325341: taper:     datestamp        = '20100301151653'                                                            
    1267482586.325354: taper:     dumplevel        = 0                                                                           
    1267482586.325368: taper:     compressed       = 0                                                                           
    1267482586.325381: taper:     encrypted        = 0                                                                           
    1267482586.325394: taper:     comp_suffix      = ''                                                                          
    1267482586.325407: taper:     encrypt_suffix   = ''                                                                          
    1267482586.325420: taper:     name             = 'DailySet4-4'                                                               
    1267482586.325433: taper:     disk             = ''                                                                          
    1267482586.325446: taper:     program          = ''                                                                          
    1267482586.325459: taper:     application      = ''                                                                          
    1267482586.325472: taper:     srvcompprog      = ''                                                                          
    1267482586.325485: taper:     clntcompprog     = ''                                                                          
    1267482586.325497: taper:     srv_encrypt      = ''                                                                          
    1267482586.325510: taper:     clnt_encrypt     = ''                                                                          
    1267482586.325523: taper:     recover_cmd      = ''                                                                          
    1267482586.325536: taper:     uncompress_cmd   = ''                                                                          
    1267482586.325549: taper:     encrypt_cmd      = ''                                                                          
    1267482586.325562: taper:     decrypt_cmd      = ''                                                                          
    1267482586.325574: taper:     srv_decrypt_opt  = ''                                                                          
    1267482586.325587: taper:     clnt_decrypt_opt = ''                                                                          
    1267482586.325600: taper:     cont_filename    = ''                                                                          
    1267482586.325613: taper:     dle_str          = (null)                                                                      
    1267482586.325625: taper:     is_partial       = 0                                                                           
    1267482586.325638: taper:     partnum          = 0                                                                           
    1267482586.325651: taper:     totalparts       = 0                                                                           
    1267482586.325699: taper:     blocksize        = 32768                                                                       
    1267482586.327790: taper: changer_label: DailySet4-4 for slot UNKNOWN                                                        
    1267482586.327827: taper: changer: >> -info                                                                                  
    1267482586.328172: taper: changer: << EXITSTATUS 0                                                                           
    1267482586.328227: taper: changer: << current 16 0 1                                                                         
    1267482586.328255: taper: changer_query: changer return was 16 0 1                                                           
    1267482586.328287: taper: changer_query: searchable = 1                                                                      
    1267482586.328309: taper: changer_label: calling changer -label DailySet4-4                                                  
    1267482586.328328: taper: changer: >> -label DailySet4-4                                                                     
    1267482586.328560: taper: changer: << EXITSTATUS 0                                                                           
    1267482586.328609: taper: changer: << 4 file://backups/backups/amanda/vtape/DailySet4                                        
    1267482586.328720: taper: putresult: 18 NEW-TAPE                                                                             
    1267482586.329968: taper: Building type 3 (FILE) header of size 32768 using:                                                 
    1267482586.330004: taper: Contents of *(dumpfile_t *)0xb6d08130:                                                             
    1267482586.330019: taper:     type             = 3 (FILE)                                                                    
    1267482586.330032: taper:     datestamp        = '20100301151653'                                                            
    1267482586.330046: taper:     dumplevel        = 1                                                                           
    1267482586.330059: taper:     compressed       = 0                                                                           
    1267482586.330072: taper:     encrypted        = 0                                                                           
    1267482586.330085: taper:     comp_suffix      = 'N'                                                                         
    1267482586.330098: taper:     encrypt_suffix   = ''                                                                          
    1267482586.330112: taper:     name             = 'scorpio.mydomain.tld'                                                           
    1267482586.330125: taper:     disk             = '/home'                                                                     
    1267482586.330138: taper:     program          = '/bin/tar'
    1267482586.330151: taper:     application      = ''
    1267482586.330164: taper:     srvcompprog      = ''
    1267482586.330178: taper:     clntcompprog     = ''
    1267482586.330191: taper:     srv_encrypt      = ''
    1267482586.330204: taper:     clnt_encrypt     = ''
    1267482586.330217: taper:     recover_cmd      = '/bin/tar -xpGf - ...'
    1267482586.330230: taper:     uncompress_cmd   = ''
    1267482586.330244: taper:     encrypt_cmd      = ''
    1267482586.330257: taper:     decrypt_cmd      = ''
    1267482586.330270: taper:     srv_decrypt_opt  = ''
    1267482586.330283: taper:     clnt_decrypt_opt = ''
    1267482586.330296: taper:     cont_filename    = ''
    1267482586.330309: taper:     dle_str          = <dle>
      <program>GNUTAR</program>
      <disk>/home</disk>
      <level>1</level>
      <auth>bsdtcp</auth>
      <record>YES</record>
      <index>YES</index>
    </dle>
    1267482586.330324: taper:     is_partial       = 0
    1267482586.330337: taper:     partnum          = 0
    1267482586.330350: taper:     totalparts       = 0
    1267482586.330363: taper:     blocksize        = 32768
    1267482612.361846: taper: putresult: 20 PARTDONE
    1267482612.362053: taper: putresult: 3 DONE
    1267482612.568082: taper: getcmd: QUIT
    1267482612.568172: taper: putresult: 2 QUITTING
    amandabackup@gemini:/var/log/amanda/server/DailySet4$
    Last edited by Dave; March 1st, 2010 at 02:29 PM. Reason: Privacy of domain name info....

  3. #3

    Default

    If anyone is interested, the problem was hardware. The RAID array for /home on the source server was degraded and had predictive failures on additional drives in the array. So HDD I/O problems reading from the source were the problem, and NOT Amanda.

Tags for this Thread

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •