Bug 17274 - procfs_write.exp, the beaker killer
Summary: procfs_write.exp, the beaker killer
Status: RESOLVED FIXED
Alias: None
Product: systemtap
Classification: Unclassified
Component: runtime (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Martin Cermak
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-08-15 11:33 UTC by Martin Cermak
Modified: 2014-08-15 15:39 UTC (History)
1 user (show)

See Also:
Host:
Target:
Build:
Last reconfirmed:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Cermak 2014-08-15 11:33:12 UTC 
Beaker is opensource (https://beaker-project.org/). In the Beaker environment, systemtap.base/prologues.exp causes the testsuite termination if run on RHEL6 or F20 (on RHEL7 this doesn't happen). However, this only happens when the testsuite is automatically scheduled by beaker scheduler. Running prologues.exp by hand (even on a beaker box) doesn't seem to reproduce the issue.

The prologues.exp calls stap_run() which, on line 63, calls "kill -INT -[exp_pid]" (commit 5a2e1a2b). This (possibly indirectly) causes "*** buffer overflow detected ***: expect terminated" which in Beaker results in the testsuite run termination. This happens on *all* architectures and quite reliably. Following is an example acquired by running ba0e072 stap bits on RHEL6/x86_64:

-----------------------------8<----------------------------------
Running ./systemtap.base/procfs_write.exp ...
Executing: kill -INT -26759
*** buffer overflow detected ***: expect terminated
======= Backtrace: =========
/lib64/libc.so.6(__fortify_fail+0x37)[0x7f9049a2c987]
/lib64/libc.so.6(+0x100870)[0x7f9049a2a870]
/lib64/libc.so.6(+0xffcc9)[0x7f9049a29cc9]
/lib64/libc.so.6(_IO_default_xsputn+0xc9)[0x7f904999e929]
/lib64/libc.so.6(_IO_vfprintf+0x41c0)[0x7f9049972480]
/lib64/libc.so.6(__vsprintf_chk+0x9d)[0x7f9049a29d6d]
/usr/lib64/libexpect5.44.1.15.so(expDiagLog+0xe3)[0x7f904a488213]
/usr/lib64/libexpect5.44.1.15.so(+0x10dfb)[0x7f904a47fdfb]
/usr/lib64/libexpect5.44.1.15.so(Exp_ExpectObjCmd+0x108)[0x7f904a482358]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x196)[0x7f904a17e0f6]
/usr/lib64/libexpect5.44.1.15.so(expMatchProcess+0x2f7)[0x7f904a481137]
/usr/lib64/libexpect5.44.1.15.so(Exp_ExpectObjCmd+0x590)[0x7f904a4827e0]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(TclObjInterpProcCore+0x147)[0x7f904a207187]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x3752f)[0x7f904a17d52f]
/usr/lib64/libtcl8.5.so(Tcl_FSEvalFileEx+0x241)[0x7f904a1e9e61]
/usr/lib64/libtcl8.5.so(+0x4eadb)[0x7f904a194adb]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x3752f)[0x7f904a17d52f]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x3af)[0x7f904a17e30f]
/usr/lib64/libtcl8.5.so(+0xc1d34)[0x7f904a207d34]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(+0x80ac6)[0x7f904a1c6ac6]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x196)[0x7f904a17e0f6]
/usr/lib64/libtcl8.5.so(+0x49923)[0x7f904a18f923]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(TclObjInterpProcCore+0x147)[0x7f904a207187]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x196)[0x7f904a17e0f6]
/usr/lib64/libtcl8.5.so(+0x40a4a)[0x7f904a186a4a]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x196)[0x7f904a17e0f6]
/usr/lib64/libtcl8.5.so(+0x40a4a)[0x7f904a186a4a]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x196)[0x7f904a17e0f6]
/usr/lib64/libtcl8.5.so(+0x40a4a)[0x7f904a186a4a]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x800fd)[0x7f904a1c60fd]
/usr/lib64/libtcl8.5.so(+0x877a9)[0x7f904a1cd7a9]
/usr/lib64/libtcl8.5.so(TclEvalObjEx+0x196)[0x7f904a17e0f6]
/usr/lib64/libtcl8.5.so(+0x40a4a)[0x7f904a186a4a]
/usr/lib64/libtcl8.5.so(+0x36a63)[0x7f904a17ca63]
/usr/lib64/libtcl8.5.so(+0x3752f)[0x7f904a17d52f]
/usr/lib64/libtcl8.5.so(Tcl_FSEvalFileEx+0x241)[0x7f904a1e9e61]
/usr/lib64/libtcl8.5.so(Tcl_EvalFile+0x2f)[0x7f904a1e9f9f]
/usr/lib64/libexpect5.44.1.15.so(exp_interpret_cmdfilename+0x4b)[0x7f904a488dfb]
expect(main+0xea)[0x400d6a]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f9049948d1d]
======= Memory map: ========
00400000-00401000 r-xp 00000000 fd:00 1187410                            /usr/bin/expect
00601000-00602000 rw-p 00001000 fd:00 1187410                            /usr/bin/expect
024e4000-02f96000 rw-p 00000000 00:00 0                                  [heap]
7f9048ee3000-7f9048ef9000 r-xp 00000000 fd:00 524290                     /lib64/libgcc_s-4.4.7-20120601.so.1
7f9048ef9000-7f90490f8000 ---p 00016000 fd:00 524290                     /lib64/libgcc_s-4.4.7-20120601.so.1
7f90490f8000-7f90490f9000 rw-p 00015000 fd:00 524290                     /lib64/libgcc_s-4.4.7-20120601.so.1
7f90490f9000-7f904910f000 r-xp 00000000 fd:00 524328                     /lib64/libresolv-2.12.so
7f904910f000-7f904930f000 ---p 00016000 fd:00 524328                     /lib64/libresolv-2.12.so
7f904930f000-7f9049310000 r--p 00016000 fd:00 524328                     /lib64/libresolv-2.12.so
7f9049310000-7f9049311000 rw-p 00017000 fd:00 524328                     /lib64/libresolv-2.12.so
7f9049311000-7f9049313000 rw-p 00000000 00:00 0 
7f9049313000-7f9049318000 r-xp 00000000 fd:00 524316                     /lib64/libnss_dns-2.12.so
7f9049318000-7f9049517000 ---p 00005000 fd:00 524316                     /lib64/libnss_dns-2.12.so
7f9049517000-7f9049518000 r--p 00004000 fd:00 524316                     /lib64/libnss_dns-2.12.so
7f9049518000-7f9049519000 rw-p 00005000 fd:00 524316                     /lib64/libnss_dns-2.12.so
7f9049519000-7f9049525000 r-xp 00000000 fd:00 524318                     /lib64/libnss_files-2.12.so
7f9049525000-7f9049725000 ---p 0000c000 fd:00 524318                     /lib64/libnss_files-2.12.so
7f9049725000-7f9049726000 r--p 0000c000 fd:00 524318                     /lib64/libnss_files-2.12.so
7f9049726000-7f9049727000 rw-p 0000d000 fd:00 524318                     /lib64/libnss_files-2.12.so
7f9049727000-7f9049729000 r-xp 00000000 fd:00 524334                     /lib64/libutil-2.12.so
7f9049729000-7f9049928000 ---p 00002000 fd:00 524334                     /lib64/libutil-2.12.so
7f9049928000-7f9049929000 r--p 00001000 fd:00 524334                     /lib64/libutil-2.12.so
7f9049929000-7f904992a000 rw-p 00002000 fd:00 524334                     /lib64/libutil-2.12.so
7f904992a000-7f9049ab5000 r-xp 00000000 fd:00 524302                     /lib64/libc-2.12.so
7f9049ab5000-7f9049cb4000 ---p 0018b000 fd:00 524302                     /lib64/libc-2.12.so
7f9049cb4000-7f9049cb8000 r--p 0018a000 fd:00 524302                     /lib64/libc-2.12.so
7f9049cb8000-7f9049cb9000 rw-p 0018e000 fd:00 524302                     /lib64/libc-2.12.so
7f9049cb9000-7f9049cbe000 rw-p 00000000 00:00 0 
7f9049cbe000-7f9049d41000 r-xp 00000000 fd:00 524310                     /lib64/libm-2.12.so
7f9049d41000-7f9049f40000 ---p 00083000 fd:00 524310                     /lib64/libm-2.12.so
7f9049f40000-7f9049f41000 r--p 00082000 fd:00 524310                     /lib64/libm-2.12.so
7f9049f41000-7f9049f42000 rw-p 00083000 fd:00 524310                     /lib64/libm-2.12.so
7f9049f42000-7f9049f44000 r-xp 00000000 fd:00 524308                     /lib64/libdl-2.12.so
7f9049f44000-7f904a144000 ---p 00002000 fd:00 524308                     /lib64/libdl-2.12.so
7f904a144000-7f904a145000 r--p 00002000 fd:00 524308                     /lib64/libdl-2.12.so
7f904a145000-7f904a146000 rw-p 00003000 fd:00 524308                     /lib64/libdl-2.12.so
7f904a146000-7f904a25f000 r-xp 00000000 fd:00 1187135                    /usr/lib64/libtcl8.5.so
7f904a25f000-7f904a45f000 ---p 00119000 fd:00 1187135                    /usr/lib64/libtcl8.5.so
7f904a45f000-7f904a46f000 rw-p 00119000 fd:00 1187135                    /usr/lib64/libtcl8.5.so
7f904a46f000-7f904a49c000 r-xp 00000000 fd:00 1187424                    /usr/lib64/libexpect5.44.1.15.so
7f904a49c000-7f904a69c000 ---p 0002d000 fd:00 1187424                    /usr/lib64/libexpect5.44.1.15.so
7f904a69c000-7f904a69e000 rw-p 0002d000 fd:00 1187424                    /usr/lib64/libexpect5.44.1.15.so
7f904a69e000-7f904a6a2000 rw-p 00000000 00:00 0 
7f904a6a2000-7f904a6c2000 r-xp 00000000 fd:00 524295                     /lib64/ld-2.12.so
7f904a8ab000-7f904a8b0000 rw-p 00000000 00:00 0 
7f904a8bf000-7f904a8c1000 rw-p 00000000 00:00 0 
7f904a8c1000-7f904a8c2000 r--p 0001f000 fd:00 524295                     /lib64/ld-2.12.so
7f904a8c2000-7f904a8c3000 rw-p 00020000 fd:00 524295                     /lib64/ld-2.12.so
7f904a8c3000-7f904a8c4000 rw-p 00000000 00:00 0 
7fff9c520000-7fff9c55b000 rw-p 00000000 00:00 0                          [stack]
7fff9c5ff000-7fff9c600000 r-xp 00000000 00:00 0                          [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]
./execrc: line 4: 16359 Aborted                 (core dumped) runtest --tool systemtap --tool_opts '' --srcdir . --debug -v -v --tool_opts 'install '
make[2]: Leaving directory `/usr/share/systemtap/testsuite'
if test -n ""; then mail  < systemtap.sum; fi
make[1]: Leaving directory `/usr/share/systemtap/testsuite'
:: [   PASS   ] :: Running 'make RUNTESTFLAGS='--debug -v -v' installcheck 2>&1' (Expected 0, got 0)

-----------------------------8<----------------------------------

Aforementioned log snippet comes from the x86_64 TESTOUT.log within following beaker run: https://url.corp.redhat.com/fd230c3.

Note that [exp_pid] refers to the stap process. When running the testcase by hand, my exp_pid was 42612: |-sshd(1117)-+-sshd(34005)---bash(34032)---make(42456)---make(42459)---sh(42460)---execrc(42495)---expect(42496)---stap(42612)---stapio(42835)-+-[{stapio}(42837){stapio}(42838)].

Could you, guys, please, have a look at this issue? So far I have no idea what exactly happens here. This can possibly also be a Beaker issue.
Comment 1 Frank Ch. Eigler 2014-08-15 12:39:29 UTC 
See also this fix for expect rpm:

* Thu Dec 12 2013 Vitezslav Crhonek <vcrhonek@redhat.com> - 5.45-13
- Use vsnprintf instead of vsprintf to avoid buffer overflow
  (it happens e.g. when running systemtap testsuite)

It looks like a backport is needed for RHEL6 etc.

At some point the stap testsuite must log more than
sizeof(bigbuf)=2000 bytes to trigger this expect bug.
This is probably this spot in systemtap.base/procfs_write.exp:

# This test string is ~4224 bytes long (66 lines of 64 chars).  The
# procfs kernel system will use a buffer of 4K. [...]
# We want to make sure we can handle > 4K worth of data properly.
set test_string \
"  0:12345678901234567890123456789012345678901234567890123456789
  1:12345678901234567890123456789012345678901234567890123456789
[...]
stap_run $test proc_write_test $test_string2 -DMAXSTRINGLEN=512 \
    -e $systemtap_write_script -m $test


and as per testsuite/lib/stap_run.exp:

    set cmd [concat stap -v $args]
    if [file readable $test_file_name] {
        lappend cmd $test_file_name
    }
    send_log "executing: $cmd\n"


Perhaps deliberately truncating $cmd there thusly:

    send_log "executing: [string range $cmd 0 1000]"

would do the trick.
Comment 2 Martin Cermak 2014-08-15 13:55:03 UTC 
Right. Thanks for the pointer. Should have noticed myself..
Comment 3 Martin Cermak 2014-08-15 15:39:20 UTC 
Fixed in commit f3596e8addd8f297c403165b2b0f98fed7c4ba6b.