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 <st...@panix.com> ----- Date: Thu, 19 Feb 2009 16:26:27 -0500 From: stan <st...@panix.com> To: "Dustin J. Mitchell" <dus...@zmanda.com> Cc: amanda users list <amanda-users@amanda.org>, "O'Connell, Debbie" <doc...@yahoo.com> Subject: Re: Next 2.6.1 issue Message-ID: <20090219212627.gd26...@teddy.fas.com> Mail-Followup-To: "Dustin J. Mitchell" <dus...@zmanda.com>, amanda users list <amanda-users@amanda.org>, "O'Connell, Debbie" <doc...@yahoo.com> References: <20090219150329.ga14...@teddy.fas.com> <42338fbf0902191034h779fc62nc52e2f9e88f51...@mail.gmail.com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <42338fbf0902191034h779fc62nc52e2f9e88f51...@mail.gmail.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 <st...@panix.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, ama...@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.