My Amanda server (2.6.0p1) has been working wonderfully well for months and months. This morning the Amanda report showed that all the DLEs have failed to write to tape, e.g.
server01 /var/log lev 0 FAILED "No new tape." I do full backups every night (filling up about 43% of a single tape and there hasn't been a significant increase in the amount of data I back up), and this morning the level 0 dumps were all on holding disk. Usually, if something does go wrong like I forget to insert the next tape, I see level 1 dumps on holding disk and just flush them. I thought that maybe the tape drive needed a clean (which I did) or there was something wrong with the tape. Due to time constraints I decided to remove the dumps on holding disk using amadmin, and inserted the next tape in line. I did an amcheck and it seemed happy with the tape and clients the way it always does. But now the job is running and I can see that the DLEs are being dumped at level 0, but that they're failing to write to tape again. It should be using the tape daily-22, and the tapelist seems fine to me, although the tape that should be used appears at the top of the list and I have a suspicion that before it usually appeared at the bottom (maybe I'm imagining that): 20091023190001 daily-22 reuse 20091022190001 daily-21b reuse 20091021190001 daily-20 reuse 20091021103229 daily-19b reuse etc, etc. I attach the taper debug log file as far as it's been written, if that helps. I haven't made any changes to the server for a very long time. The only change I made recently was to label a new tape called daily-19b for Tuesday night's backup run. I would really appreciate some advice on how to troubleshoot this problem. Thanks.
1256320801.941816: taper: pid 5054 ruid 500 euid 500: start at Fri Oct 23 19:00:01 2009 1256320801.943866: taper: taper: pid 5054 executable taper version 2.6.0p1 1256320801.947534: taper: pid 5054 ruid 500 euid 500: rename at Fri Oct 23 19:00:01 2009 1256320801.947749: taper: getcmd: START-TAPER 20091023190001 1256320805.323785: taper: putresult: 25 TAPER-OK 1256320974.212662: taper: getcmd: FILE-WRITE 03-00005 /data1/holdingdisk/20091023190001/server01._var_log.0 server01 /var/log 0 20091023190001 1073741824 1256320974.213096: taper: putresult: 26 REQUEST-NEW-TAPE 1256320974.231223: taper: getcmd: NEW-TAPE 1256320978.956280: taper: Building type 1 (TAPESTART) header of size 32768 using: 1256320978.956320: taper: Contents of *(dumpfile_t *)0x935ac58: 1256320978.956334: taper: type = 1 (TAPESTART) 1256320978.956351: taper: datestamp = '20091023190001' 1256320978.956362: taper: dumplevel = 0 1256320978.956373: taper: compressed = 0 1256320978.956384: taper: encrypted = 0 1256320978.956395: taper: comp_suffix = '' 1256320978.956406: taper: encrypt_suffix = '' 1256320978.956417: taper: name = 'daily-22' 1256320978.956428: taper: disk = '' 1256320978.956438: taper: program = '' 1256320978.956449: taper: dumper = '' 1256320978.956459: taper: srvcompprog = '' 1256320978.956470: taper: clntcompprog = '' 1256320978.956480: taper: srv_encrypt = '' 1256320978.956491: taper: clnt_encrypt = '' 1256320978.956501: taper: recover_cmd = '' 1256320978.956512: taper: uncompress_cmd = '' 1256320978.956522: taper: encrypt_cmd = '' 1256320978.956533: taper: decrypt_cmd = '' 1256320978.956543: taper: srv_decrypt_opt = '' 1256320978.956554: taper: clnt_decrypt_opt = '' 1256320978.956564: taper: cont_filename = '' 1256320978.956574: taper: is_partial = 0 1256320978.956585: taper: partnum = 0 1256320978.956596: taper: totalparts = 0 1256320978.956606: taper: blocksize = 32768 1256320978.957231: taper: putresult: 18 NEW-TAPE 1256321083.042522: taper: putresult: 10 FAILED 1256321083.042999: taper: getcmd: FILE-WRITE 01-00007 /data1/holdingdisk/20091023190001/server01._var_log.0 server01 /var/log 0 20091023190001 1073741824 1256321083.043293: taper: putresult: 10 FAILED 1256321083.043675: taper: getcmd: FILE-WRITE 01-00008 /data2/holdingdisk/20091023190001/server04._var_log.0 server04 /var/log 0 20091023190001 1073741824 1256321083.043972: taper: putresult: 10 FAILED 1256321083.044438: taper: getcmd: FILE-WRITE 01-00009 /data2/holdingdisk/20091023190001/server04._var_log.0 server04 /var/log 0 20091023190001 1073741824 1256321083.044697: taper: putresult: 10 FAILED 1256321083.045136: taper: getcmd: FILE-WRITE 01-00010 /data2/holdingdisk/20091023190001/server02._var_log.0 server02 /var/log 0 20091023190001 1073741824 1256321083.045410: taper: putresult: 10 FAILED 1256321083.045779: taper: getcmd: FILE-WRITE 01-00011 /data2/holdingdisk/20091023190001/server02._var_log.0 server02 /var/log 0 20091023190001 1073741824 1256321083.046061: taper: putresult: 10 FAILED 1256321083.046469: taper: getcmd: FILE-WRITE 01-00012 /data2/holdingdisk/20091023190001/server03._var_log.0 server03 /var/log 0 20091023190001 1073741824 1256321083.046730: taper: putresult: 10 FAILED 1256321083.047060: taper: getcmd: FILE-WRITE 01-00013 /data2/holdingdisk/20091023190001/server03._var_log.0 server03 /var/log 0 20091023190001 1073741824 1256321083.047295: taper: putresult: 10 FAILED
