ASSERT (api.startstop) dispatch.c:681 dcontext-last_exit == get_starting_linkstub()

[derekbruening]

From [email protected] on June 19, 2012 22:41:21

happened in one suite run. can't repro though:

debug-internal-32: 106 tests passed, **** 2 tests failed: ****
code_api|client.timer
code_api|api.startstop => Application api.startstop (1942). Internal Error Internal DynamoRIO Error: /work/dr/build_suite/src/core/dispatch.c:681 dcontext-last_exit == get_starting_linkstub() || IF_APP_EXPORTS(dcontext-last_exit == get_native_exec_linkstub() ||) IF_WINDOWS_ELSE_0(dcontext-last_exit == get_asynch_linkstub())

Original issue: http://code.google.com/p/dynamorio/issues/detail?id=813

[derekbruening]

From [email protected] on October 16, 2012 14:02:22

This happens for me locally and I see it pop up on the bot. =/

I'll mark it flaky along with the other ones in an upcoming CL.

debug-internal-32: 112 tests passed, **** 3 tests failed, of which 1 were flaky: ****
code_api|linux.persist_FLAKY
code_api|client.drmgr-test
code_api|api.startstop => Application /usr/local/google/home/rnk/dynamorio/build/test-clone/build_debug-internal-32/suite/tests/bin/api.startstop (20032). Internal Error Internal DynamoRIO Error: ../core/dispatch.c:688 dcontext-last_exit == get_starting_linkstub() || IF_APP_EXPORTS(dcontext-last_exit == get_native_exec_linkstub() ||) IF_WINDOWS_ELSE_0(dcontext-last_exit == get_asynch_linkstub())

[derekbruening]

From [email protected] on December 17, 2012 09:43:22

link to an instance on the bot: http://build.chromium.org/p/client.dynamorio/builders/linux-dr/builds/113

[derekbruening]

From [email protected] on March 24, 2014 12:22:20

The assert fails because the value of dcontext->last_exit is get_syscall_linkstub(). When this happens, there is no syscall pending (i.e., get_at_syscall() is false). Failure is sporadic, about 30% of runs in my build when running this test alone. It seems to always fail in a pre-commit from an empty directory.

[derekbruening]

From [email protected] on April 07, 2014 11:45:01

Labels: Component-Tests

[derekbruening]

From [email protected] on April 07, 2014 14:39:31

Taking a look as part of a push to reduce flakiness

This one is rather bizarre -- have not yet figured out how it got back to dispatch in such a weird way:

(gdb) p dcontext->last_exit
$1 = (linkstub_t *) 0xf72e772c <linkstub_syscall>
(gdb) p dcontext->next_tag
$2 = (app_pc) 0xf70747b4 <dr_app_stop> "U\211\345]\303U\211\345S\203\354\004\350\364\036\377\377\201\303;81"
(gdb) p /x dcontext->upcontext.upcontext.mcontext.esp
$4 = 0xffcd7f70
(gdb) p /x dcontext->upcontext.upcontext.mcontext.ebp
$5 = 0x4524c960

I got it w/ -loglevel 2:

dispatch: target = 0x08048c40
Entry into F393(0x08048c40).0x4e6bbd6c (trace head)(shared)
Exit from sourceless ibl: bb jmp*
(target 0xf70747b4 not in cache)

dispatch: target = 0xf70747b4

Found DynamoRIO stopping point: thread 31596 returning to app @0xf70747b4

appstart_cleanup: found stopping point
==dr_app_stop
os_switch_seg_to_context: switching to app, setting gs to 0x63
os_switch_seg_to_context to app: set_thread_area successful for thread 31596 base 0xf7714700

initial dispatch: target = 0xf70747b4
Call stack:
Call stack:
0xf70747b4
frame ptr 0x4524c960 => parent 0xfbad2887, 0x4524c9a7
priv_mcontext_t @0x4e69a3c0
xax = 0x00000017
xbx = 0x00000002
xcx = 0xff8cc0ec
xdx = 0x00000017
xsi = 0xff8cc0ec
xdi = 0x00000017
xbp = 0x4524c960
xsp = 0xff8cbf90
ymm0= 0x0000000000000000000000000000000000000000000000000000000000000000
ymm1= 0x00504d5338312e32000000000000000000000000000000000000000000000000
ymm2= 0x0000000000000000000000000000000000000000000000000000000000000000
ymm3= 0xff00000000000000ffffffffffffffff00000000000000000000000000000000
ymm4= 0x0000000000000000000000000000000000000000000000000000000000000000
ymm5= 0x00504d5338312e32000000000000000000000000000000000000000000000000
ymm6= 0x0000000000000000000000000000000000000000000000000000000000000000
ymm7= 0x0000000000000000000000000000000000000000000000000000000000000000
mxcsr=0x00001f80
eflags = 0x00000296
pc = 0xf70747b4
SYSLOG_ERROR: Application /work/dr/git/build_x86_dbg_tests/suite/tests/bin/api.startstop (31596). Internal Error: DynamoRIO debug check failure: /work/dr/git/src/core/dispatch.c:715 dcontext->last_exit == get_starting_linkstub() || IF_APP_EXPORTS(dcontext->last_exit == get_native_exec_linkstub() ||) IF_WINDOWS_ELSE_0(dcontext->last_exit == get_asynch_linkstub())

It should look like this to transition from stop to start (with "all done"
printed natively in between):

Found DynamoRIO stopping point: thread 31585 returning to app @0xf70747b4

appstart_cleanup: found stopping point
==dr_app_stop
os_switch_seg_to_context: switching to app, setting gs to 0x63
os_switch_seg_to_context to app: set_thread_area successful for thread 31585 base 0xf772c700
os_switch_seg_to_context: switching to dr, setting gs to 0x63
os_switch_seg_to_context to DR: set_thread_area successful for thread 31585 base 0x4fb1ab70

initial dispatch: target = 0x080495d0

global logfile has 2 dr_app_start earlier and then this line with 8 of them:
dr_app_start in thread 31596dr_app_start in thread 31596dr_app_start in thread 31596dr_app_start in thread 31596dr_app_start in thread 31596dr_app_start in thread 31596dr_app_start in thread 31596dr_app_start in thread 31596SYSLOG_ERROR: Application /work/dr/git/build_x

so #11 is not printed. but the "all done" is printed -- so it clearly
made it to native. but somehow it comes back to dispatch bypassing the
regular start stuff, with the mcontext set to what it was on the go-native
at dr_app_stop. how did it get there? we don't have the prior stack
value which makes it tough. clearly it swapped to the dstack.

(gdb) bt
#0 syscall_0args () at /work/dr/git/src/core/x86/x86.asm:1249
#1 0x4e69a3c0 in ?? ()
#2 0xf728bce3 in os_read (f=0, buf=0x4e6f6557, count=1) at /work/dr/git/src/core/unix/os.c:3436
#3 0xf70f76a5 in notify (priority=SYSLOG_ERROR, internal=false, synch=false, substitution_num=3, prefix=0xf72f38dc "SYSLOG_ERROR",
fmt=0xf72f50f0 "Application %s (%s). Internal Error: %s") at /work/dr/git/src/core/utils.c:1961
#4 0xf70f7b96 in report_dynamorio_problem (dcontext=0x4e69a3c0, dumpcore_flag=8, exception_addr=0x0,
report_ebp=0x4e6f6dc0 "\364noN`(\017\367\300\243iN\b",
fmt=0xf72f3864 "DynamoRIO debug check failure: %s:%d %s\n(Error occurred @%d frags)") at /work/dr/git/src/core/utils.c:2210
#5 0xf70f2860 in internal_error (file=0xf72ef5fc "/work/dr/git/src/core/dispatch.c", line=715,
expr=0xf72efe08 "dcontext->last_exit == get_starting_linkstub() || IF_APP_EXPORTS(dcontext->last_exit == get_native_exec_linkstub() ||) IF_WINDOWS_ELSE_0(dcontext->last_exit == get_asynch_linkstub())") at /work/dr/git/src/core/utils.c:174
#6 0xf70deca9 in dispatch_enter_dynamorio (dcontext=0x4e69a3c0) at /work/dr/git/src/core/dispatch.c:711
#7 0xf70dba55 in dispatch (dcontext=0x4e69a3c0) at /work/dr/git/src/core/dispatch.c:158
#8 0x4e6b1f87 in ?? ()

Owner: [email protected]

[derekbruening]

From [email protected] on April 07, 2014 14:58:54

Current theory is that it hits the vsyscall hook while native. But why it would be nondet is unclear.

[derekbruening]

From [email protected] on April 08, 2014 10:14:58

That's it, all right. I have a fix that seems solid.

[derekbruening]

From [email protected] on April 08, 2014 12:12:54

This issue was closed by revision r2639 .

Status: Fixed

[hgreving2304]

xref #2694