There seems to be some question as to whether this message went out or no,
so I am resending it. Apologies if it is a repost.
Debbie said to point out that this is the message that contains the taper
debug file.
----- Forwarded message from stan <stanb AT panix DOT com> -----
Date: Thu, 19 Feb 2009 16:26:27 -0500
From: stan <stanb AT panix DOT com>
To: "Dustin J. Mitchell" <dustin AT zmanda DOT com>
Cc: amanda users list <amanda-users AT amanda DOT org>,
"O'Connell, Debbie" <docrtp AT yahoo DOT com>
Subject: Re: Next 2.6.1 issue
Message-ID: <20090219212627.GD26670 AT teddy.fas DOT com>
Mail-Followup-To: "Dustin J. Mitchell" <dustin AT zmanda DOT com>,
amanda users list <amanda-users AT amanda DOT org>,
"O'Connell, Debbie" <docrtp AT yahoo DOT com>
References: <20090219150329.GA14691 AT teddy.fas DOT com>
<42338fbf0902191034h779fc62nc52e2f9e88f514cf AT mail.gmail DOT com>
Mime-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <42338fbf0902191034h779fc62nc52e2f9e88f514cf AT mail.gmail DOT com>
X-Editor: gVim
X-Operating-System: Debian GNU/Linux
X-Kernel-Version: 2.4.23
X-Uptime: 14:34:11 up 283 days, 20:56, 2 users, load average: 0.00, 0.01, 0.00
User-Agent: Mutt/1.5.4i
Status: RO
On Thu, Feb 19, 2009 at 01:34:13PM -0500, Dustin J. Mitchell wrote:
> On Thu, Feb 19, 2009 at 10:03 AM, stan <stanb AT panix DOT com> wrote:
> > Any thoughts as to what might be going on here?
>
> >From the look of it, the taper begins writing a TAPESTART header
> (well, two -- one for each child device), then 11s later, fails and
> goes looking for a new tape. It finds a new tape, but driver says "no
> soup for you!"
>
> 1235054407.366438: taper: getcmd: NO-NEW-TAPE "runtapes volumes already
> written"
>
> and everything shuts down.
>
> The question is *why* the write to the device failed. I don't see any
> good clues in the logfile. What does
> amdevcheck DailyDump rait:{file:/vtapes/DailyDump/vtape5,tape:/dev/nst0}
> give you, now that the perl errors are resolved?
>
We're still chasing this down. First of all,
amanda@amanda:/opt/amanda/sbin$ ./amdevcheck DailyDump
"rait:{file:/vtapes/DailyDump/vtape5,tape:/dev/nst0}"
SUCCESS
And: amcheck DailyDump is happy.
But the backup fails & the changer.debug log doesn't give enough info to be
terribly useful so we looked at the taper debug in
/tmp/amanda/server/DailyDump/taperxxx.debug
Here's the taper log. We know that we should be looking for DailyDump04
which corresponds to vtape5, slot 5 (yes, I know that the 00 based labeling
is confusing but its always worked just fine & we've never got around to
making the labels match the vtape/slot 1 base) Anyway, a label is just
a string and doesn't care if it has anything meaningful in its name.
Notice that at the end, it looks for the next tape label "DailyDump05" but
it thinks it should be slot 4, vtape 4 (DailyDump05 is actually slot 6, vtape
6)!
It looks like it is decrementing the count by 1, instead of incrementing &
it must be confused about the current slot when it starts.
1235075062.212100: taper: pid 5702 ruid 1001 euid 1001 version 2.6.1: start at
Thu Feb 19 15:24:22 2009
1235075062.212638: taper: taper: pid 5702 executable taper version 2.6.1
1235075062.214580: taper: pid 5702 ruid 1001 euid 1001 version 2.6.1: rename at
Thu Feb 19 15:24:22 2009
1235075062.214814: taper: getcmd: START-TAPER 20090219152422
1235075062.216254: taper: changer: >> -info
1235075062.437569: taper: changer: << EXITSTATUS 0
1235075062.437620: taper: changer: << current 25 0 1
1235075062.437637: taper: changer_query: changer return was 25 0 1
1235075062.437665: taper: changer_query: searchable = 1
1235075062.437674: taper: changer_find: looking for DailyDump04 changer is
searchable = 1
1235075062.437685: taper: changer_search: DailyDump04
1235075062.437697: taper: changer: >> -search DailyDump04
1235075062.885062: taper: changer: << EXITSTATUS 0
1235075062.885109: taper: changer: << 5
rait:{file:/vtapes/DailyDump/vtape5,tape:/dev/nst0}
1235075062.998720: taper: changer_label: DailyDump04 for slot 5
1235075062.998736: taper: changer: >> -info
1235075062.998848: taper: changer: << EXITSTATUS 0
1235075062.998857: taper: changer: << current 25 0 1
1235075062.998866: taper: changer_query: changer return was 25 0 1
1235075062.998881: taper: changer_query: searchable = 1
1235075062.998889: taper: changer_label: calling changer -label DailyDump04
1235075062.998897: taper: changer: >> -label DailyDump04
1235075062.998990: taper: changer: << EXITSTATUS 0
1235075062.998999: taper: changer: << 5
rait:{file:/vtapes/DailyDump/vtape5,tape:/dev/nst0}
1235075062.999058: taper: putresult: 25 TAPER-OK
1235075062.999357: taper: getcmd: FILE-WRITE 00-00001
/dumpdisk/20090219092310/AP0502._dev_md_dsk_d0.1 AP0502 /dev/md/dsk/d0 1
20090219092310 0
1235075062.999538: taper: putresult: 26 REQUEST-NEW-TAPE
1235075062.999619: taper: getcmd: NEW-TAPE
1235075063.124729: taper: Building type 1 (TAPESTART) header of size 32768
using:
1235075063.124776: taper: Contents of *(dumpfile_t *)0x64bc50:
1235075063.124784: taper: type = 1 (TAPESTART)
1235075063.124792: taper: datestamp = '20090219152422'
1235075063.124799: taper: dumplevel = 0
1235075063.124806: taper: compressed = 0
1235075063.124814: taper: encrypted = 0
1235075063.124821: taper: comp_suffix = ''
1235075063.124828: taper: encrypt_suffix = ''
1235075063.124835: taper: name = 'DailyDump04'
1235075063.124842: taper: disk = ''
1235075063.124849: taper: program = ''
1235075063.124856: taper: application = ''
1235075063.124863: taper: srvcompprog = ''
1235075063.124870: taper: clntcompprog = ''
1235075063.124877: taper: srv_encrypt = ''
1235075063.124884: taper: clnt_encrypt = ''
1235075063.124891: taper: recover_cmd = ''
1235075063.124898: taper: uncompress_cmd = ''
1235075063.124905: taper: encrypt_cmd = ''
1235075063.124912: taper: decrypt_cmd = ''
1235075063.124919: taper: srv_decrypt_opt = ''
1235075063.124926: taper: clnt_decrypt_opt = ''
1235075063.124932: taper: cont_filename = ''
1235075063.124979: taper: dle_str = (null)
1235075063.124987: taper: is_partial = 0
1235075063.124994: taper: partnum = 0
1235075063.125001: taper: totalparts = 0
1235075063.125008: taper: blocksize = 32768
1235075063.160905: taper: Building type 1 (TAPESTART) header of size 32768
using:
1235075063.160940: taper: Contents of *(dumpfile_t *)0x2aaaac003b40:
1235075063.160948: taper: type = 1 (TAPESTART)
1235075063.160955: taper: datestamp = '20090219152422'
1235075063.160962: taper: dumplevel = 0
1235075063.160969: taper: compressed = 0
1235075063.160976: taper: encrypted = 0
1235075063.160983: taper: comp_suffix = ''
1235075063.160990: taper: encrypt_suffix = ''
1235075063.160997: taper: name = 'DailyDump04'
1235075063.161004: taper: disk = ''
1235075063.161011: taper: program = ''
1235075063.161018: taper: application = ''
1235075063.161024: taper: srvcompprog = ''
1235075063.161031: taper: clntcompprog = ''
1235075063.161038: taper: srv_encrypt = ''
1235075063.161045: taper: clnt_encrypt = ''
1235075063.161052: taper: recover_cmd = ''
1235075063.161058: taper: uncompress_cmd = ''
1235075063.161065: taper: encrypt_cmd = ''
1235075063.161072: taper: decrypt_cmd = ''
1235075063.161079: taper: srv_decrypt_opt = ''
1235075063.161085: taper: clnt_decrypt_opt = ''
1235075063.161092: taper: cont_filename = ''
1235075063.161099: taper: dle_str = (null)
1235075063.161106: taper: is_partial = 0
1235075063.161113: taper: partnum = 0
1235075063.161120: taper: totalparts = 0
1235075063.161127: taper: blocksize = 32768
1235075066.040874: taper: changer_label: DailyDump04 for slot UNKNOWN
1235075066.040905: taper: changer: >> -info
1235075066.041131: taper: changer: << EXITSTATUS 0
1235075066.041142: taper: changer: << current 25 0 1
1235075066.041151: taper: changer_query: changer return was 25 0 1
1235075066.041167: taper: changer_query: searchable = 1
1235075066.041175: taper: changer_label: calling changer -label DailyDump04
1235075066.041183: taper: changer: >> -label DailyDump04
1235075066.041266: taper: changer: << EXITSTATUS 0
1235075066.041275: taper: changer: << 5
rait:{file:/vtapes/DailyDump/vtape5,tape:/dev/nst0}
1235075066.041323: taper: putresult: 18 NEW-TAPE
1235075071.400399: taper: putresult: 26 REQUEST-NEW-TAPE
1235075071.401141: taper: changer: >> -info
1235075071.401314: taper: getcmd: NO-NEW-TAPE "runtapes volumes already written"
1235075071.401580: taper: changer: << EXITSTATUS 0
1235075071.401596: taper: changer: << current 25 0 1
1235075071.401608: taper: changer_query: changer return was 25 0 1
1235075071.401624: taper: changer_query: searchable = 1
1235075071.401632: taper: changer_find: looking for DailyDump05 changer is
searchable = 1
1235075071.401639: taper: changer_search: DailyDump05
1235075071.401647: taper: changer: >> -search DailyDump05
1235075082.258211: taper: changer: << EXITSTATUS 1
1235075082.258281: taper: changer: << <error> Volume 'DailyDump05' not found
1235075082.258290: taper: changer: ERROR <error> Volume 'DailyDump05' not found
1235075082.258312: taper: changer: >> -slot current
1235075082.610615: taper: changer: << EXITSTATUS 0
1235075082.610659: taper: changer: << 4
rait:{file:/vtapes/DailyDump/vtape4,tape:/dev/nst0}
1235075082.610866: taper: putresult: 10 FAILED
--
One of the main causes of the fall of the roman empire was that, lacking
zero, they had no way to indicate successful termination of their C
programs.
----- End forwarded message -----
--
One of the main causes of the fall of the roman empire was that, lacking
zero, they had no way to indicate successful termination of their C
programs.
|
