3.4.5 amcheck segfault in try_match with cleaning tape in library

Jason L Tibbitts III <[email protected]> Mon, 03 Jul 2017 16:35:26 -0500
Newsgroups gmane.comp.archivers.amanda.devel
Message-ID <[email protected]>
I reported this on the user list but received no response.  Reporting
here with slightly more detail.

I replaced a tape in my 48-slot library with a cleaning tape since I'd
rather not bother with manually cleaning the drive.  The library is an
Overland Neo T48, and supports auto-cleaning with the tape in any slot.
But unfortunately this appears to make amcheck (or rather the
amcheck-device subprocess) segfault:

AMANDA:backup2:amanda/server/math> amcheck -s math
Amanda Tape Server Host Check
-----------------------------
NOTE: Holding disk '/local/amanda/work': 7617304 MB disk space
available, using 7617204 MB
ERROR: amcheck-device terminated with signal 11
Server check took 1.145 seconds
(brought to you by Amanda 3.4.5)

The generated amcheck-device log file doesn't appear to have any
problems; it's included at the end, as is a gdb backtrace.

amanda.conf has:
  labelstr "^C[0-9][0-9][0-9][0-9][0-9]$

My changer definition:

define changer neo-t48 {
        tpchanger "chg-robot:/dev/sg7"
        property "tape-device" "0=tape:/dev/nst0"
        device-property "LEOM" "TRUE"
        device-property "BLOCK_SIZE" "512k"
        changerfile "/var/lib/amanda/chg-robot-dev-sg7"
}

The cleaning table has label "CLNU01L1".  I thought maybe that any
non-matching label would cause problems, but if I change labelstr such
that it would match all of the labels then things still fail with the
cleaning tape installed.  And if I leave the tape out, there's no
segfault even if I set labelstr to something which matches only some, or
none, of the loaded tapes.

It doesn't seem to matter which slot the cleaning tape is in.

The backtrace below makes it pretty clear that the problem is running a
regex match on the CLNU01L1 label.  I tried digging into the Perl code
but the async nature of it all makes it a bit tough to follow, and I
honestly have no idea where in the Perl code it's actually failing.  Can
I get it to log which of the step functions it's running when, or
otherwise get it to tell me more about what's happening under the hood?

I would really like to let my library auto-clean itself so any help
getting this resolved would be great.  I can apply patches and whatnot
if anyone has suggestions about what in the code might need tweaking.  I
can speak Perl but my C skills are pretty poor.

 - J<

Here's the amcheck-device log file:

Wed Jun 28 16:04:56.256642259 2017: pid 7589: thd-0x1e71e00: amcheck-device: pid 7589 ruid 33 euid 33 version 3.4.5: start at Wed Jun 28 16:04:56 2017
Wed Jun 28 16:04:56.257046150 2017: pid 7589: thd-0x1e71e00: amcheck-device: reading config file /etc/amanda/math/amanda.conf
Wed Jun 28 16:04:56.292549518 2017: pid 7589: thd-0x1e71e00: amcheck-device: pid 7589 ruid 33 euid 33 version 3.4.5: rename at Wed Jun 28 16:04:56 2017
Wed Jun 28 16:04:56.324069360 2017: pid 7589: thd-0x1e71e00: amcheck-device: chg-robot: using statefile '/var/lib/amanda/chg-robot-dev-sg7'
Wed Jun 28 16:04:56.343513329 2017: pid 7589: thd-0x1e71e00: amcheck-device: invoking /usr/sbin/mtx -f /dev/sg7 status
Wed Jun 28 16:04:57.061363299 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:   Storage Changer /dev/sg7:1 Drives, 48 Slots ( 0 Import/Export )
Wed Jun 28 16:04:57.061438518 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx: Data Transfer Element 0:Full (Storage Element 36 Loaded):VolumeTag = C00036L6
Wed Jun 28 16:04:57.061497882 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 1:Full :VolumeTag=C00001L6
Wed Jun 28 16:04:57.061553266 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 2:Full :VolumeTag=C00002L6
Wed Jun 28 16:04:57.061595450 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 3:Full :VolumeTag=C00003L6
Wed Jun 28 16:04:57.061635749 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 4:Full :VolumeTag=C00004L6
Wed Jun 28 16:04:57.061675558 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 5:Full :VolumeTag=C00005L6
Wed Jun 28 16:04:57.061712923 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 6:Full :VolumeTag=C00006L6
Wed Jun 28 16:04:57.061750358 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 7:Full :VolumeTag=C00007L6
Wed Jun 28 16:04:57.061789958 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 8:Full :VolumeTag=C00008L6
Wed Jun 28 16:04:57.061831793 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 9:Full :VolumeTag=C00009L6
Wed Jun 28 16:04:57.061895278 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 10:Full :VolumeTag=C00010L6
Wed Jun 28 16:04:57.061935646 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 11:Full :VolumeTag=C00011L6
Wed Jun 28 16:04:57.061973430 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 12:Full :VolumeTag=C00012L6
Wed Jun 28 16:04:57.062010516 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 13:Full :VolumeTag=C00013L6
Wed Jun 28 16:04:57.062047672 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 14:Full :VolumeTag=C00014L6
Wed Jun 28 16:04:57.062084897 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 15:Full :VolumeTag=C00015L6
Wed Jun 28 16:04:57.062121982 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 16:Full :VolumeTag=C00016L6
Wed Jun 28 16:04:57.062168706 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 17:Full :VolumeTag=C00017L6
Wed Jun 28 16:04:57.062206700 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 18:Full :VolumeTag=C00018L6
Wed Jun 28 16:04:57.062244274 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 19:Full :VolumeTag=C00019L6
Wed Jun 28 16:04:57.062281779 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 20:Full :VolumeTag=C00020L6
Wed Jun 28 16:04:57.062319074 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 21:Full :VolumeTag=C00021L6
Wed Jun 28 16:04:57.062356718 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 22:Full :VolumeTag=C00022L6
Wed Jun 28 16:04:57.062394153 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 23:Full :VolumeTag=C00023L6
Wed Jun 28 16:04:57.062432007 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 24:Full :VolumeTag=C00024L6
Wed Jun 28 16:04:57.062506667 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 25:Full :VolumeTag=C00025L6
Wed Jun 28 16:04:57.062544940 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 26:Full :VolumeTag=C00026L6
Wed Jun 28 16:04:57.062582934 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 27:Full :VolumeTag=C00027L6
Wed Jun 28 16:04:57.062620508 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 28:Full :VolumeTag=C00028L6
Wed Jun 28 16:04:57.062657594 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 29:Full :VolumeTag=C00029L6
Wed Jun 28 16:04:57.062695168 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 30:Full :VolumeTag=C00030L6
Wed Jun 28 16:04:57.062732184 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 31:Full :VolumeTag=C00031L6
Wed Jun 28 16:04:57.062772832 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 32:Full :VolumeTag=C00032L6
Wed Jun 28 16:04:57.062814317 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 33:Full :VolumeTag=C00033L6
Wed Jun 28 16:04:57.062852101 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 34:Full :VolumeTag=C00034L6
Wed Jun 28 16:04:57.062899942 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 35:Full :VolumeTag=C00035L6
Wed Jun 28 16:04:57.062936958 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 36:Empty
Wed Jun 28 16:04:57.062975021 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 37:Full :VolumeTag=C00037L6
Wed Jun 28 16:04:57.063012666 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 38:Full :VolumeTag=C00038L6
Wed Jun 28 16:04:57.063049542 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 39:Full :VolumeTag=C00039L6
Wed Jun 28 16:04:57.063086418 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 40:Full :VolumeTag=C00040L6
Wed Jun 28 16:04:57.063122875 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 41:Full :VolumeTag=C00041L6
Wed Jun 28 16:04:57.063159402 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 42:Full :VolumeTag=C00042L6
Wed Jun 28 16:04:57.063195789 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 43:Full :VolumeTag=C00043L6
Wed Jun 28 16:04:57.063232316 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 44:Full :VolumeTag=C00044L6
Wed Jun 28 16:04:57.063268494 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 45:Full :VolumeTag=C00045L6
Wed Jun 28 16:04:57.063304811 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 46:Full :VolumeTag=C00046L6
Wed Jun 28 16:04:57.063341268 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 47:Full :VolumeTag=C00047L6
Wed Jun 28 16:04:57.063380239 2017: pid 7589: thd-0x1e71e00: amcheck-device: mtx:       Storage Element 48:Full :VolumeTag=CLNU01L1
Wed Jun 28 16:04:57.063491007 2017: pid 7589: thd-0x1e71e00: amcheck-device: neo-t48: updating state

Here is a backtrace:

Core was generated by `/usr/bin/perl /usr/lib64/amanda/amcheck-device math math'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  strlen () at ../sysdeps/x86_64/strlen.S:106
106             movdqu  (%rax), %xmm4
[Current thread is 1 (Thread 0x7fca1b365300 (LWP 8421))]
(gdb) bt
#0  strlen () at ../sysdeps/x86_64/strlen.S:106
#1  0x00007fca19ae3a47 in __regexec (preg=preg@entry=0x1d16f90, string=string@entry=0x0, nmatch=nmatch@entry=0,
    pmatch=pmatch@entry=0x0, eflags=eflags@entry=0) at regexec.c:240
#2  0x00007fca18f3f0d8 in try_match (regex=0x1d16f90, str=str@entry=0x0, errbuf=errbuf@entry=0x7ffd26fd4490) at match.c:312
#3  0x00007fca18f3f8ef in do_match (regex=regex@entry=0x1cef980 "^C[0-9][0-9][0-9][0-9][0-9]$", str=str@entry=0x0,
    match_newline=match_newline@entry=1) at match.c:344
#4  0x00007fca18f40706 in match_labelstr (labelstr=labelstr@entry=0x18e1640, autolabel=autolabel@entry=0x1cf6f10,
    label=label@entry=0x0, barcode=barcode@entry=0x1cf7fb0 "CLNU01L1", meta=meta@entry=0x0, storage=<optimized out>) at match.c:1283
#5  0x00007fca12d37ef7 in _wrap_match_labelstr (my_perl=<optimized out>, cv=<optimized out>) at Amanda/Util.c:3679
#6  0x00007fca1ae33c50 in Perl_pp_entersub (my_perl=0x893010) at pp_hot.c:3988
#7  0x00007fca1ae2c116 in Perl_runops_standard (my_perl=0x893010) at run.c:41
#8  0x00007fca1adac1ce in Perl_call_sv (my_perl=<optimized out>, sv=sv@entry=0x1cfdc48, flags=flags@entry=12) at perl.c:2807
#9  0x00007fca119e71ef in amglue_source_callback_simple (data=data@entry=0x1cf1730) at Amanda/MainLoop.c:1683
#10 0x00007fca183d789d in g_timeout_dispatch (source=0x1d03460, callback=0x7fca119e70f0 <amglue_source_callback_simple>,
    user_data=0x1cf1730) at gmain.c:4674
#11 0x00007fca183d6e52 in g_main_dispatch (context=0x1526aa0) at gmain.c:3203
#12 g_main_context_dispatch (context=context@entry=0x1526aa0) at gmain.c:3856
#13 0x00007fca183d71d0 in g_main_context_iterate (context=context@entry=0x1526aa0, block=block@entry=1, dispatch=dispatch@entry=1,
    self=<optimized out>) at gmain.c:3929
#14 0x00007fca183d727c in g_main_context_iteration (context=0x1526aa0, context@entry=0x0, may_block=1) at gmain.c:3990
#15 0x00007fca18f394d1 in event_loop_wait (wait_eh=0x0, nonblock=0, return_when_empty=0) at event.c:427
#16 0x00007fca18f398c8 in event_loop_run () at event.c:336
#17 0x00007fca119e7bb5 in run_c () at Amanda/MainLoop.c:1572
#18 0x00007fca119e7c13 in _wrap_run_c (my_perl=<optimized out>, cv=<optimized out>) at Amanda/MainLoop.c:2019
#19 0x00007fca1ae33c50 in Perl_pp_entersub (my_perl=0x893010) at pp_hot.c:3988
#20 0x00007fca1ae2c116 in Perl_runops_standard (my_perl=0x893010) at run.c:41
#21 0x00007fca1adb3e56 in S_run_body (oldscope=<optimized out>, my_perl=<optimized out>) at perl.c:2483
#22 perl_run (my_perl=0x893010) at perl.c:2406
#23 0x0000000000400ce9 in main (argc=<optimized out>, argv=<optimized out>, env=<optimized out>) at perlmain.c:116

 - J<