Re: 3.4.5 amcheck segfault in try_match with cleaning tape in library

Jason,

It's fine to repost if you get no answer.
I haven't read all my mail since my vacation return.

The stacktrace show that perl call match_labelstr with an undef label, 
which is  a bug.
There is many call to match_labelstr, so we must find which one.
Can you add a debugging statement before each call to match_labelstr? 
(probably in perl/Amanda/Taper/Scan/traditional.pm)
Something like: debug("I'm here");


On 03/07/17 05:35 PM, Jason L Tibbitts III wrote:
> 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<
>
This message is the property of CARBONITE, INC. and may contain confidential or privileged information.
If this message has been delivered to you by mistake, then do not copy or deliver this message to anyone.  Instead, destroy it and notify me by reply e-mail