Re: Amanda 3.5.1 - "ERROR: amcheck-device terminated with signal 11"

/tmp/amanda/server/daily/amcheck-device.20201011120931.debug (lexical)

Sun Oct 11 12:09:31.912123219 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 35:Full :VolumeTag=000038L7
Sun Oct 11 12:09:31.912170629 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 36:Full :VolumeTag=000039L7
Sun Oct 11 12:09:31.912217715 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 37:Full :VolumeTag=000040L7
Sun Oct 11 12:09:31.912264266 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 38:Full :VolumeTag=000041L7
Sun Oct 11 12:09:31.912313021 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 39:Full :VolumeTag=000042L7
Sun Oct 11 12:09:31.912354905 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 40:Empty
Sun Oct 11 12:09:31.912392783 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 41:Empty
Sun Oct 11 12:09:31.912430299 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 42:Empty
Sun Oct 11 12:09:31.912472391 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 43:Full :VolumeTag=000043L7
Sun Oct 11 12:09:31.912515070 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 44:Empty
Sun Oct 11 12:09:31.912552958 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 45:Empty
Sun Oct 11 12:09:31.912590453 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 46:Empty
Sun Oct 11 12:09:31.912632567 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 47:Full :VolumeTag=CLN001CU
Sun Oct 11 12:09:31.912678933 2020: pid 22002: thd-0xe8e600: amcheck-device: mtx:       Storage 
Element 48:Full :VolumeTag=CLN002CU
Sun Oct 11 12:09:31.912816794 2020: pid 22002: thd-0xe8e600: amcheck-device: NEO200x48: updating state
Sun Oct 11 12:09:31.922463203 2020: pid 22002: thd-0xe8e600: amcheck-device: warning: Use of 
uninitialized value in numeric eq (==) at /usr/local/share/perl/5.22.1/Amanda/Taper/Scan/lexical.pm 
line 106.
Sun Oct 11 12:09:31.922577733 2020: pid 22002: thd-0xe8e600: amcheck-device: warning: Use of 
uninitialized value in numeric eq (==) at /usr/local/share/perl/5.22.1/Amanda/Taper/Scan/lexical.pm 
line 106.
Sun Oct 11 12:09:31.922630514 2020: pid 22002: thd-0xe8e600: amcheck-device: warning: Use of 
uninitialized value in numeric eq (==) at /usr/local/share/perl/5.22.1/Amanda/Taper/Scan/lexical.pm 
line 106.


/tmp/amanda/server/daily/amcheck-device.20201011121015.debug (traditional)

Sun Oct 11 12:10:16.358496965 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 33:Full :VolumeTag=000036L7
Sun Oct 11 12:10:16.358551835 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 34:Full :VolumeTag=000037L7
Sun Oct 11 12:10:16.358600321 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 35:Full :VolumeTag=000038L7
Sun Oct 11 12:10:16.358647199 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 36:Full :VolumeTag=000039L7
Sun Oct 11 12:10:16.358693381 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 37:Full :VolumeTag=000040L7
Sun Oct 11 12:10:16.358739526 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 38:Full :VolumeTag=000041L7
Sun Oct 11 12:10:16.358785636 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 39:Full :VolumeTag=000042L7
Sun Oct 11 12:10:16.358831765 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 40:Empty
Sun Oct 11 12:10:16.358873441 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 41:Empty
Sun Oct 11 12:10:16.358911735 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 42:Empty
Sun Oct 11 12:10:16.358954276 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 43:Full :VolumeTag=000043L7
Sun Oct 11 12:10:16.358999694 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 44:Empty
Sun Oct 11 12:10:16.359037603 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 45:Empty
Sun Oct 11 12:10:16.359074776 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 46:Empty
Sun Oct 11 12:10:16.359116468 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 47:Full :VolumeTag=CLN001CU
Sun Oct 11 12:10:16.359165851 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 48:Full :VolumeTag=CLN002CU
Sun Oct 11 12:10:16.359302222 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: updating state
Sun Oct 11 12:10:16.361076728 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: loading 
label 'Bio-Research-002'
Sun Oct 11 12:10:16.361442086 2020: pid 22053: thd-0x8d3600: amcheck-device: new 
Amanda::Changer::Error: type='failed', reason='notfound', message='label 'Bio-Research-002' not 
recognized or not found'
Sun Oct 11 12:10:16.366368914 2020: pid 22053: thd-0x8d3600: amcheck-device: 
Amanda::Taper::Scan::traditional oldest reusable volume not found
Sun Oct 11 12:10:16.366554771 2020: pid 22053: thd-0x8d3600: amcheck-device: 
Amanda::Taper::Scan::traditional stage 2: scan for any reusable volume
Sun Oct 11 12:10:16.368764426 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: too early 
for another 'status' invocation
Sun Oct 11 12:10:16.369065443 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: requested 
volume is already in drive 1
Sun Oct 11 12:10:16.369356360 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: polling 
'tape:/dev/nst2' to see if it's ready
Sun Oct 11 12:10:16.372082593 2020: pid 22053: thd-0x8d3600: amcheck-device: Device is in variable 
block size
Sun Oct 11 12:10:34.060734012 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: setting 
current slot to 15
Sun Oct 11 12:10:34.065396987 2020: pid 22053: thd-0x8d3600: amcheck-device: 
Amanda::Taper::Scan::traditional result: 'Bio-Research-003' on tape:/dev/nst2 slot 15, mode 2
Sun Oct 11 12:10:34.068600268 2020: pid 22053: thd-0x8d3600: amcheck-device: invoking /usr/sbin/mtx 
-f /dev/tape/by-id/scsi-1BDT_FlexStor_II_00MX64200626_LL0 status
Sun Oct 11 12:10:34.759469907 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:   Storage Changer 
/dev/tape/by-id/scsi-1BDT_FlexStor_II_00MX64200626_LL0:2 Drives, 48 Slots ( 0 Import/Export )
Sun Oct 11 12:10:34.759559408 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx: Data Transfer 
Element 0:Full (Storage Element 14 Loaded):VolumeTag = 000013L7
Sun Oct 11 12:10:34.759657617 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx: Data Transfer 
Element 1:Full (Storage Element 15 Loaded):VolumeTag = 000003L7
Sun Oct 11 12:10:34.759713971 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 1:Empty
Sun Oct 11 12:10:34.759773323 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 2:Empty
Sun Oct 11 12:10:34.759823463 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 3:Full :VolumeTag=000015L7
Sun Oct 11 12:10:34.759885919 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 4:Full :VolumeTag=000016L7
Sun Oct 11 12:10:34.759936527 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 5:Full :VolumeTag=000017L7
Sun Oct 11 12:10:34.759990844 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 6:Full :VolumeTag=000014L7
Sun Oct 11 12:10:34.760039976 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 7:Empty
Sun Oct 11 12:10:34.760083991 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 8:Empty
Sun Oct 11 12:10:34.760133666 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 9:Full :VolumeTag=000021L7
Sun Oct 11 12:10:34.760184739 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 10:Full :VolumeTag=000018L7
Sun Oct 11 12:10:34.760231776 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 11:Empty
Sun Oct 11 12:10:34.760274501 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 12:Empty
Sun Oct 11 12:10:34.760320009 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 13:Full :VolumeTag=000001L7
Sun Oct 11 12:10:34.760366311 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 14:Empty
Sun Oct 11 12:10:34.760409529 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 15:Empty
Sun Oct 11 12:10:34.760457577 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 16:Full :VolumeTag=000004L7
Sun Oct 11 12:10:34.760510620 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 17:Full :VolumeTag=000005L7
Sun Oct 11 12:10:34.760574058 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 18:Full :VolumeTag=000006L7
Sun Oct 11 12:10:34.760649466 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 19:Full :VolumeTag=000007L7
Sun Oct 11 12:10:34.760699582 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 20:Full :VolumeTag=000008L7
Sun Oct 11 12:10:34.760752231 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 21:Full :VolumeTag=000009L7
Sun Oct 11 12:10:34.760800054 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 22:Full :VolumeTag=000010L7
Sun Oct 11 12:10:34.760848396 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 23:Full :VolumeTag=000011L7
Sun Oct 11 12:10:34.760896150 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 24:Full :VolumeTag=000012L7
Sun Oct 11 12:10:34.760943886 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 25:Full :VolumeTag=000028L7
Sun Oct 11 12:10:34.760991310 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 26:Full :VolumeTag=000029L7
Sun Oct 11 12:10:34.761037996 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 27:Full :VolumeTag=000030L7
Sun Oct 11 12:10:34.761084613 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 28:Full :VolumeTag=000031L7
Sun Oct 11 12:10:34.761131572 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 29:Full :VolumeTag=000032L7
Sun Oct 11 12:10:34.761178211 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 30:Full :VolumeTag=000033L7
Sun Oct 11 12:10:34.761225513 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 31:Full :VolumeTag=000034L7
Sun Oct 11 12:10:34.761272012 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 32:Full :VolumeTag=000035L7
Sun Oct 11 12:10:34.761325637 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 33:Full :VolumeTag=000036L7
Sun Oct 11 12:10:34.761373334 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 34:Full :VolumeTag=000037L7
Sun Oct 11 12:10:34.761420697 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 35:Full :VolumeTag=000038L7
Sun Oct 11 12:10:34.761468300 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 36:Full :VolumeTag=000039L7
Sun Oct 11 12:10:34.761514824 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 37:Full :VolumeTag=000040L7
Sun Oct 11 12:10:34.761573183 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 38:Full :VolumeTag=000041L7
Sun Oct 11 12:10:34.761621522 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 39:Full :VolumeTag=000042L7
Sun Oct 11 12:10:34.761665454 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 40:Empty
Sun Oct 11 12:10:34.761704884 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 41:Empty
Sun Oct 11 12:10:34.761743707 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 42:Empty
Sun Oct 11 12:10:34.761786802 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 43:Full :VolumeTag=000043L7
Sun Oct 11 12:10:34.761831406 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 44:Empty
Sun Oct 11 12:10:34.761870251 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 45:Empty
Sun Oct 11 12:10:34.761912233 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 46:Empty
Sun Oct 11 12:10:34.761955765 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 47:Full :VolumeTag=CLN001CU
Sun Oct 11 12:10:34.762031735 2020: pid 22053: thd-0x8d3600: amcheck-device: mtx:       Storage 
Element 48:Full :VolumeTag=CLN002CU
Sun Oct 11 12:10:34.762180292 2020: pid 22053: thd-0x8d3600: amcheck-device: NEO200x48: updating state
Sun Oct 11 12:10:34.768573227 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_utime   : 0
Sun Oct 11 12:10:34.768600132 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_stime   : 0
Sun Oct 11 12:10:34.768611861 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_maxrss  : 30220
Sun Oct 11 12:10:34.768622366 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_ixrss   : 0
Sun Oct 11 12:10:34.768632346 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_idrss   : 0
Sun Oct 11 12:10:34.768641844 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_isrss   : 0
Sun Oct 11 12:10:34.768651422 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_minflt  : 7267
Sun Oct 11 12:10:34.768660818 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_majflt  : 0
Sun Oct 11 12:10:34.768670385 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_nswap   : 0
Sun Oct 11 12:10:34.768679557 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_inblock : 0
Sun Oct 11 12:10:34.768688927 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_oublock : 192
Sun Oct 11 12:10:34.768698189 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_msgsnd  : 0
Sun Oct 11 12:10:34.768707231 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_msgrcv  : 0
Sun Oct 11 12:10:34.768716257 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_nsignals: 0
Sun Oct 11 12:10:34.768725327 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_nvcsw   : 11
Sun Oct 11 12:10:34.768734424 2020: pid 22053: thd-0x8d3600: amcheck-device: ru_nivcsw  : 26
Sun Oct 11 12:10:34.769475404 2020: pid 22053: thd-0x8d3600: amcheck-device: pid 22053 finish time 
Sun Oct 11 12:10:34 2020


On 10/11/20 12:58 AM, Nathan Stratton Treadway wrote:
> On Sat, Oct 10, 2020 at 23:50:17 -0400, Chris Hoogendyk wrote:
>> Wow!
>>
>>     amanda@marlin:~/daily$ amcheck -s -otaperscan=taper_traditional daily
>>     Amanda Tape Server Host Check
>>     -----------------------------
>>     NOTE: Holding disk '/amanda3': 913514496 KB disk space available, using 808656896 KB
>>     NOTE: Holding disk '/amanda4': 158228480 KB disk space available, using 53370880 KB
>>     NOTE: Holding disk '/amanda5': 1636618240 KB disk space available, using 1531760640 KB
>>     Searching for label 'Bio-Research-002':label 'Bio-Research-002' not recognized or not found
>>     slot 13:slot 13 not in use-slots (14-36)
>>     slot 14: volume 'Bio-Research-013' is still active and cannot be overwritten
>>     slot 15: volume 'Bio-Research-003'
>>     Will write to volume 'Bio-Research-003' in slot 15.
>>     NOTE: skipping tape-writable test
>>     Server check took 175.512 seconds
>>     (brought to you by Amanda 3.5.1)
>>     amanda@marlin:~/daily$
>>
>> That worked! Interestingly, doing an `amcheck -s daily` after that
>> fails just as before. The amanda.conf uses taper_oldest.
> Okay, this lends support to the theory that the crash is actually
> happening in "scan" operation, rather than in some later part of the
> amcheck-driver/taper process.
>   
> (Were there any error/warning messages written to the amcheck-device log
> file for that run?)
>
>> So, maybe if I temporarily go to the different algorithm, it will
>> work. Right now the backups are already running and dumping to
> Yeah, it might well work, and if so -- and if you don't care which
> tape(s) are used next -- then simply switching to taper_traditional
> would probably be the easiest approach to getting new dumps actually
> written to tape....
>
>
> If the order the tapes are used does matter to you, I think it should
> probably be possible to fix the bug in taper_oldest (oldest.pm) to get
> it working (but I'm not really sure how much debugging effort it will
> involve...).
>
> If you are interested to attempt that, the next thing I would check is
> to see what happens with -otaperscan=taper_lexical (assuming that is also
> defined in your amanda.conf).  The "lexical" and "oldest" algorithms
> both use the tape-drive inventory (while "traditional" does not), so
> that test will help narrow the problem down to just "oldest" or to the
> tape-inventory part of the code....
>
>
>
> 						Nathan
>
>
>
> ----------------------------------------------------------------------------
> Nathan Stratton Treadway  -  [email protected]  -  Mid-Atlantic region
> Ray Ontko & Co.  -  Software consulting services  -   http://www.ontko.com/
>   GPG Key: http://www.ontko.com/~nathanst/gpg_key.txt   ID: 1023D/ECFB6239
>   Key fingerprint = 6AD8 485E 20B9 5C71 231C  0C32 15F3 ADCD ECFB 6239

-- 
---------------

Chris Hoogendyk

-
    O__  ---- Systems Administrator, Retired
   c/ /'_ --- Biology & Geosciences Departments
  (*) \(*) -- 315 Morrill Science Center III
~~~~~~~~~~ - University of Massachusetts, Amherst

<[email protected]>

---------------

Erdös 4