Amanda-Users

confusing problem with NO-NEW-TAPE

2008-05-07 14:27:08
Subject: confusing problem with NO-NEW-TAPE
From: "Nathan Barss" <nbarss AT cambric DOT com>
To: <amanda-users AT amanda DOT org>
Date: Wed, 7 May 2008 12:21:34 -0600
Please forgive my n00bness.  This is probably a simple configuration error on 
my part, but I am having a problem getting Amanda to flush to tape.  Everything 
else seems to work fine.  The report when I run amflush looks like this (and is 
similar to the report from amdump):

Hostname: backup.merp.com
Org     : Main merp Amanda
Config  : Main
Date    : May 7, 2008

There are 7051204K of dumps left in the holding disk.
They will be flushed on the next run.

The next tape Amanda expects to use is: a new tape.
The next new tape already labelled is: merpMain-001.

FAILURE DUMP SUMMARY:
   172.16.1.134       /test           lev 0  FAILED "No new tape."
   172.16.1.134       /test           lev 0  FAILED "No new tape."
   172.16.1.134       /test           lev 0  FAILED [too many taper retries]
   172.16.1.23        /backup         lev 0  FAILED "No new tape."
   172.16.1.23        /backup         lev 0  FAILED "No new tape."
   172.16.1.23        /backup         lev 0  FAILED [too many taper retries]
   backup.merp.com    /etc/amanda     lev 0  FAILED "No new tape."
   backup.merp.com    /etc/amanda     lev 0  FAILED "No new tape."
   backup.merp.com    /etc/amanda     lev 0  FAILED [too many taper retries]
   backup.merp.com    /var/lib/amanda lev 0  FAILED "No new tape."
   backup.merp.com    /var/lib/amanda lev 0  FAILED "No new tape."
   backup.merp.com    /var/lib/amanda lev 0  FAILED [too many taper retries]


STATISTICS:
                          Total       Full      Incr.
                        --------   --------   --------
Estimate Time (hrs:min)    0:00
Run Time (hrs:min)         0:00
Dump Time (hrs:min)        0:00       0:00       0:00
Output Size (meg)           0.0        0.0        0.0
Original Size (meg)         0.0        0.0        0.0
Avg Compressed Size (%)     --         --         -- 
Filesystems Dumped            0          0          0
Avg Dump Rate (k/s)         --         --         -- 

Tape Time (hrs:min)        0:00       0:00       0:00
Tape Size (meg)             0.0        0.0        0.0
Tape Used (%)               0.0        0.0        0.0
Filesystems Taped             0          0          0

Chunks Taped                  0          0          0
Avg Tp Write Rate (k/s)     --         --         -- 

?
DUMP SUMMARY:
                                       DUMPER STATS               TAPER STATS 
HOSTNAME     DISK        L ORIG-KB  OUT-KB  COMP%  MMM:SS   KB/s MMM:SS   KB/s
-------------------------- ------------------------------------- -------------
172.16.1.134 /test       0 FAILED --------------------------------------------
172.16.1.23  /backup     0 FAILED --------------------------------------------
backup.merp /etc/amanda 0 FAILED --------------------------------------------
backup.merp -lib/amanda 0 FAILED --------------------------------------------

(brought to you by Amanda version 2.6.0)


The next new tape is available, and the changer seems to be working fine.  
amcheck works without issue, and the tapes were labeled with amlabel.

Information about the system:
CentOS 5.1 x86
tpchanger "chg-zd-mtx"
tapedev "tape:/dev/tape-nst0"
changerfile "/etc/amanda/Main/changer.conf"
changerdev "/dev/changer" 
Amanda 2.6.0 from zmanda rpm
/proc/scsi/scsi entries for my changer, which is an Exabyte Magnum 1x7
Host: scsi1 Channel: 00 Id: 00 Lun: 00
  Vendor: EXABYTE  Model: EXB-210          Rev: B00E
  Type:   Medium Changer                   ANSI SCSI revision: 04
Host: scsi1 Channel: 00 Id: 01 Lun: 00
  Vendor: IBM      Model: ULTRIUM-TD2      Rev: 4C60
  Type:   Sequential-Access                ANSI SCSI revision: 03

The emulation on the changer can be changed to others, and I have experimented 
with them as well.  The behavior doesn't seem to change.

Here is the cut from the amflush log:
amflush: start at Wed May  7 11:17:37 MDT 2008
amflush: datestamp 20080507111733
amflush: starttime 20080507111733
amflush: starttime-locale-independent 2008-05-07 11:17:37 MDT
FLUSH 172.16.1.134 /test 20080430161259 0 
/var/dumps/20080430161259/172.16.1.134._test.0
FLUSH 172.16.1.23 /backup 20080430161259 0 
/var/dumps/20080430161259/172.16.1.23._backup.0
FLUSH backup.merp.com /etc/amanda 20080430161259 0 
/var/dumps/20080430161259/backup.merp.com._etc_amanda.0
FLUSH backup.merp.com /var/lib/amanda 20080430161259 0 
/var/dumps/20080430161259/backup.merp.com._var_lib_amanda.0
ENDFLUSH
driver: pid 17097 executable driver version 2.6.0
driver: adding holding disk 0 dir /var/dumps size 183439360 chunksize 1048576
reserving 183439360 out of 183439360 for degraded-mode dumps
driver: send-cmd time 0.004 to taper: START-TAPER 20080507111733
driver: start time 0.006 inparallel 4 bandwidth 8000 diskspace 183439360  dir 
OBSOLETE datestamp 20080507111733 driver: drain-ends tapeq FIRST big-dumpers 
sssS
taper: pid 17098 executable taper version 2.6.0
taper: using label `merpMain-005' date `20080507111733'
driver: result time 1.582 from taper: TAPER-OK 
driver: send-cmd time 1.583 to taper: FILE-WRITE 00-00001 
/var/dumps/20080430161259/172.16.1.134._test.0 172.16.1.134 /test 0 
20080430161259 0
driver: startaflush: FIRST 172.16.1.134 /test 130833 204472320
driver: state time 1.583 free kps: 8000 space: 183439360 taper: writing 
idle-dumpers: 4 qlen tapeq: 3 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idle
driver: interface-state time 1.583 if default: free 8000
driver: hdisk-state time 1.583 hdisk 0: free 183439360 dumpers 0
driver: state time 1.583 free kps: 8000 space: 183439360 taper: writing 
idle-dumpers: 4 qlen tapeq: 3 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idle
driver: interface-state time 1.583 if default: free 8000
driver: hdisk-state time 1.583 hdisk 0: free 183439360 dumpers 0
driver: result time 1.583 from taper: REQUEST-NEW-TAPE 00-00001
driver: send-cmd time 1.583 to taper: NO-NEW-TAPE
driver: state time 1.583 free kps: 8000 space: 183439360 taper: writing 
idle-dumpers: 4 qlen tapeq: 3 runq: 0 roomq: 0 wakeup: 0 driver-idle: not-idle
driver: interface-state time 1.583 if default: free 8000
driver: hdisk-state time 1.583 hdisk 0: free 183439360 dumpers 0
driver: result time 1.583 from taper: FAILED 00-00001 INPUT-GOOD TAPE-ERROR "" 
"No new tape."
driver: finished-cmd time 1.583 taper wrote 172.16.1.134:/test
driver: taper will retry 172.16.1.134 /test
driver: send-cmd time 1.583 to taper: FILE-WRITE 00-00002 
/var/dumps/20080430161259/172.16.1.134._test.0 172.16.1.134 /test 0 
20080430161259 0
...
...
...
0 wakeup: 0 driver-idle: no-dumpers
driver: interface-state time 1.588 if default: free 8000
driver: hdisk-state time 1.588 hdisk 0: free 183439360 dumpers 0
driver: QUITTING time 1.588 telling children to quit
driver: send-cmd time 1.588 to taper: QUIT
taper: DONE
driver: FINISHED time 2.596

The final debug for the changer script gives me this:

1210180658.538961: chg-zd-mtx: pid 17678 ruid 500 euid 500: start at Wed May  7 
11:17:38 2008
11:17:38 Using config file /etc/amanda/Main/changer.conf
11:17:38 Arg info:
         $# = 2
         $0 = "/usr/libexec/amanda/chg-zd-mtx"
         $1 = "-label"
         $2 = "merpMain-005"
11:17:38 Running: mtxRunning: status
11:17:38 Exit code: 0
         Stdout:
  Storage Changer /dev/changer:1 Drives, 7 Slots ( 0 Import/Export )
Data Transfer Element 0:Full (Storage Element 5 Loaded):VolumeTag = 000105      
                        
      Storage Element 1:Full :VolumeTag=000106                              
      Storage Element 2:Full :VolumeTag=000114                              
      Storage Element 3:Full :VolumeTag=000110                              
      Storage Element 4:Full :VolumeTag=000113                              
      Storage Element 5:Empty:VolumeTag=                                    
      Storage Element 6:Full :VolumeTag=000103                              
      Storage Element 7:Full :VolumeTag=                                    
11:17:38 Config info:
         firstslot = "1"
         lastslot = "7"
         cleanslot = "7"
         cleancycle = "120"
         offline_before_unload = "0"
         unloadpause = "0"
         autoclean = "0"
         autocleancount = "99"
         havereader = "1"
         driveslot = "0"
         poll_drive_ready = "3"
         initial_poll_delay = "0"
         max_drive_wait = "120"
11:17:38 STATUS -> currently loaded slot = 5
         -> currently loaded barcode = "000105"
11:17:38 LABEL -> Adding label "merpMain-005" with barcode "000105" for slot 5 
into /etc/amanda/Main/changer-barcodes
         -> already synced
11:17:38 Exit (0) -> 5 tape:/dev/tape-nst0
1210180658.884833: chg-zd-mtx: pid 17851 finish time Wed May  7 11:17:38 2008

While logged in as the Amanda user, I am able to manually move tapes around in 
the changer using mtx and write to the tape with tar.  amtape works well also.

There are new tapes in the changer, and the tape that it is looking for 
(merpMain-005) is in the drive when the script starts.

I'm not able to determine what is going on.  Perhaps I just need help 
interpreting the logs?  Has anyone experienced a similar issue?

Thanks...


Nathan Barss
CIS Administrator
Cambric Corporation
nbarss AT cambric DOT com


_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

Privileged/Confidential Information may be contained in this message.  
If you are not the addressee indicated in this message (or responsible 
for delivery of the message to such person), you may not print, retain, 
copy nor disseminate this message or any part of it to anyone and you 
should notify the sender by reply email and destroy this message.  
Neglecting this clause could be a breach of confidence.  Please advise 
the sender of this message immediately if you or your employer does not 
consent to Internet email for messages of this kind.  Opinions, 
conclusions and other information in this message that are not related 
to the official business of Cambric shall be understood as neither given 
nor endorsed by it. 
Scanning of this message and addition of this footer is performed
by SurfControl E-mail Filter software in conjunction with virus detection 
software.

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