crash while running script with `dump.py`

[honggyukim]

Please see below.

$ uftrace record -S ./scripts/dump.py ls
uftrace_begin(ctx)
  record  : True
  version : v0.9.3-15-gaaa0 ( dwarf python tui perf sched dynamic )
  cmds    : ls

21373629.142397426 126391: [entry] strrchr(402570) depth: 0
  args[0] <type 'str'>: ls
  args[1] <type 'str'>: /
...
21373523.928701122 126288: [exit ] __freading(4027f0) depth: 0
21373523.928728563 126288: [entry] fflush(4027a0) depth: 0
  args[0] <type 'long'>: 140368809711136
21373523.928728563 126288: [exit ] fflush(4027a0) depth: 0
  retval  <type 'int'>: 0
21373523.928775829 126288: [entry] fclose(402480) depth: 0
  args[0] <type 'long'>: 140368809711136
*** Error in `ls': free(): corrupted unsorted chunks: 0x00000000021e0e40 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7faa28d577e5]
/lib/x86_64-linux-gnu/libc.so.6(+0x8037a)[0x7faa28d6037a]
/lib/x86_64-linux-gnu/libc.so.6(cfree+0x4c)[0x7faa28d6453c]
/usr/lib/x86_64-linux-gnu/libpython2.7.so(+0x161039)[0x7faa26815039]
/usr/lib/x86_64-linux-gnu/libpython2.7.so(+0xc903a)[0x7faa2677d03a]
/home/honggyu/usr/lib/libmcount.so(+0x1c05a)[0x7faa292e805a]
/home/honggyu/usr/lib/libmcount.so(+0x9943)[0x7faa292d5943]
/home/honggyu/usr/lib/libmcount.so(+0xcffe)[0x7faa292d8ffe]
/home/honggyu/usr/lib/libmcount.so(+0x26501)[0x7faa292f2501]
/home/honggyu/usr/lib/libmcount.so(+0x264e6)[0x7faa292f24e6]
======= Memory map: ========
00400000-0041e000 r-xp 00000000 fc:00 224788660                          /bin/ls
0061d000-0061e000 r--p 0001d000 fc:00 224788660                          /bin/ls
0061e000-0061f000 rw-p 0001e000 fc:00 224788660                          /bin/ls
0061f000-00620000 rw-p 00000000 00:00 0
02084000-0222f000 rw-p 00000000 00:00 0                                  [heap]
7faa20000000-7faa20021000 rw-p 00000000 00:00 0
...
7ffd3c3fd000-7ffd3c3ff000 r-xp 00000000 00:00 0                          [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]
WARN: process crashed by signal 6: Aborted (si_code: -6)
WARN: Backtrace from uftrace:
WARN: =====================================
WARN: [1] (free[402340] <= _IO_setb[7faa28d5b54b])
WARN: [0] (fclose[402480] <= <412f3a>[412f3a])
WARN: child terminated by signal: 6: Aborted

[honggyukim]

Here is the backtrace.

Thread 2.1 "ls" received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff7fc4900 (LWP 136516)]
0x00007ffff75e5428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
54      ../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
(gdb) bt
#0  0x00007ffff75e5428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
#1  0x00007ffff75e702a in __GI_abort () at abort.c:89
#2  0x00007ffff76277ea in __libc_message (do_abort=do_abort@entry=2, fmt=fmt@entry=0x7ffff7740ed8 "*** Error in `%s': %s: 0x%s ***\n") at ../sysdeps/posix/lib
c_fatal.c:175
#3  0x00007ffff763037a in malloc_printerr (ar_ptr=<optimized out>, ptr=<optimized out>, str=0x7ffff7740f78 "free(): corrupted unsorted chunks", action=3) at m
alloc.c:5006
#4  _int_free (av=<optimized out>, p=<optimized out>, have_lock=0) at malloc.c:3867
#5  0x00007ffff763453c in __GI___libc_free (mem=<optimized out>) at malloc.c:2968
#6  0x00007ffff50e5039 in dict_dealloc.lto_priv.395 (mp=0x7ffff7e795c8) at ../Objects/dictobject.c:1044
#7  0x00007ffff504d03a in tupledealloc.lto_priv.451 (op=0x7ffff7e72ed0) at ../Objects/tupleobject.c:222
#8  0x00007ffff7bb84ba in python_uftrace_exit (sc_ctx=<optimized out>) at /home/honggyu/work/uftrace/git/uftrace/utils/script-python.c:595
#9  0x00007ffff7ba59c3 in script_hook_exit (rstack=0x78f6b8, mtdp=0x7ffff7fc3818) at /home/honggyu/work/uftrace/git/uftrace/libmcount/mcount.c:941
#10 mcount_exit_filter_record (mtdp=mtdp@entry=0x7ffff7fc3818, rstack=rstack@entry=0x78f6b8, retval=<optimized out>, retval@entry=0x7fffffffe060) at /home/hon
ggyu/work/uftrace/git/uftrace/libmcount/mcount.c:1133
#11 0x00007ffff7ba907e in __plthook_exit (retval=0x7fffffffe060) at /home/honggyu/work/uftrace/git/uftrace/libmcount/plthook.c:972
#12 plthook_exit (retval=0x7fffffffe060) at /home/honggyu/work/uftrace/git/uftrace/libmcount/plthook.c:1017
#13 0x00007ffff7bc16d1 in plthook_return () at /home/honggyu/work/uftrace/git/uftrace/arch/x86_64/plthook.S:85
#14 0x00007ffff7bc16b6 in plt_hooker () at /home/honggyu/work/uftrace/git/uftrace/arch/x86_64/plthook.S:68
#15 0x0000000000000000 in ?? ()

[honggyukim]

cgdb backtrace points the problem was occurred in Py_XDECREF.

560│ int python_uftrace_exit(struct script_context *sc_ctx)
561│ {
562│         if (unlikely(!pFuncExit))
563│                 return -1;
564│
565│         pthread_mutex_lock(&python_interpreter_lock);
566│
567│         /* Entire arguments are passed into a single dictionary. */
568│         PyObject *pDict = __PyDict_New();
569│
570│         /* Setup common info in both entry and exit into a dictionary */
571│         setup_common_context(&pDict, sc_ctx);
572│
573│         /* Add time duration info */
574│         insert_dict_ull(pDict, PYCTX(DURATION), sc_ctx->duration);
575│
576│         if (sc_ctx->arglen)
577│                 setup_argument_context(&pDict, true, sc_ctx);
578│
579│         /* Python function arguments must be passed in a tuple. */
580│         PyObject *pythonContext = __PyTuple_New(1);
581│         __PyTuple_SetItem(pythonContext, 0, pDict);
582│
583│         /* Call python function "uftrace_exit". */
584│         __PyObject_CallObject(pFuncExit, pythonContext);
585│         if (debug) {
586│                 if (__PyErr_Occurred() && !python_error_reported) {
587│                         pr_dbg("uftrace_exit failed:\n");
588│                         __PyErr_Print();
589│
590│                         python_error_reported = true;
591│                 }
592│         }
593│
594│         /* Free PyTuple. */
595├───────> Py_XDECREF(pythonContext);
596│
597│         pthread_mutex_unlock(&python_interpreter_lock);
598│
599│         return 0;
600│ }

(gdb) p pythonContext
$1 = ({'name': 'free', 'timestamp': 21379455582526782L, 'duration': 28694L, 'depth': 1, 'address': <unknown at remote 0x745ae0>, 'tid': <unknown at remote 0x7
45ac8>},)

[honggyukim]

After applying the following change.

diff --git a/utils/script-python.c b/utils/script-python.c
index 15499c3..1976d6d 100644
--- a/utils/script-python.c
+++ b/utils/script-python.c
@@ -591,9 +591,6 @@ int python_uftrace_exit(struct script_context *sc_ctx)
                }
        }

-       /* Free PyTuple. */
-       Py_XDECREF(pythonContext);
-
        pthread_mutex_unlock(&python_interpreter_lock);

        return 0;

It doesn't get crashed, but also doesn't finish like #943.

[honggyukim]

It's not crashed in Ubuntu 18.04, but only crashed in Ubuntu 16.04.