LTTng bugs repository: Issueshttps://bugs.lttng.org/https://bugs.lttng.org/themes/lttng/favicon/a.ico?14249722912021-03-24T19:46:38ZLTTng bugs repository
Redmine LTTng-UST - Bug #1301 (Resolved): lttng-ust erroneously truncates sequences by NULL-terminating themhttps://bugs.lttng.org/issues/13012021-03-24T19:46:38ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>The following commit introduces a regression that causes lttng-tools' test suite to fail:</p>
<pre>
commit 2792781482a58865c7504100d8c1ba6db41193d1
Author: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Date: Mon Mar 22 16:59:38 2021 -0400
ABI refactoring: sequence and array of text: copy input as string
Within the lttng-modules writeback instrumentation, which exposes a
tracepoint probe API similar to LTTng-UST, we had a long standing issue
where a fixed-size array of text was used to copy a string input into
the trace.
This is fine as long as the input string is actually backed by a
fixed-size array, but if the input string is variable-size, and may be
smaller than the array size, this led to out-of-bound memory reads
beyond the input string NULL terminating character.
Change the behavior of the array/sequence of text to stop copying the
input as soon as the array/sequence size limit (-1) or the input's NULL
terminating character is found, and add zeroed padding for the rest of
the array/sequence within the ring buffer.
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Change-Id: Icc3f31c12bdd8018e5e4b7ea146fe842371054d6
</pre>
<pre>
❯ ./tests/regression/ust/linking/test_linking
1..32
ok 1 - Running application dynamically linked to providers, no preload
ok 2 - No events logged when running demo application without preloading providers
ok 3 - demo_static, resulting trace found
ok 4 - demo_static, total number of events logged is correct
ok 5 - demo_static, ust_tests_demo:starting event found in trace with a correct integer argument
not ok 6 - demo_static, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 1
not ok 7 - demo_static, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 2
not ok 8 - demo_static, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 3
not ok 9 - demo_static, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 4
not ok 10 - demo_static, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 5
ok 11 - demo_static, ust_tests_demo:done event found in resulting trace with a correct integer argument
ok 12 - demo_static, ust_tests_demo3:done event found in resulting trace with a correct integer argument
ok 13 - demo_builtin, resulting trace found
ok 14 - demo_builtin, total number of events logged is correct
ok 15 - demo_builtin, ust_tests_demo:starting event found in trace with a correct integer argument
not ok 16 - demo_builtin, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 1
not ok 17 - demo_builtin, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 2
not ok 18 - demo_builtin, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 3
not ok 19 - demo_builtin, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 4
not ok 20 - demo_builtin, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 5
ok 21 - demo_builtin, ust_tests_demo:done event found in resulting trace with a correct integer argument
ok 22 - demo_builtin, ust_tests_demo3:done event found in resulting trace with a correct integer argument
ok 23 - demo_preload, resulting trace found
ok 24 - demo_preload, total number of events logged is correct
ok 25 - demo_preload, ust_tests_demo:starting event found in trace with a correct integer argument
not ok 26 - demo_preload, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 1
not ok 27 - demo_preload, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 2
not ok 28 - demo_preload, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 3
not ok 29 - demo_preload, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 4
not ok 30 - demo_preload, ust_tests_demo2:loop event found in trace and arguments are correct, iteration 5
ok 31 - demo_preload, ust_tests_demo:done event found in resulting trace with a correct integer argument
ok 32 - demo_preload, ust_tests_demo3:done event found in resulting trace with a correct integer argument
# Killing (signal SIGTERM) lttng-sessiond and lt-lttng-sessiond pids: 1322178 1322179
</pre>
<p>This test runs an application that makes use of a <code>ctf_sequence_text</code> to trace the <code>"test"</code> string.<br />Before applying this change, readers correctly interpret the field as <code>"test"</code>. After, they only see <code>"tes"</code>.</p>
<p>The change introduced in the commit appears to assume that text sequences are null-terminated, which they are not (they are effectively P-strings).</p>
<p>All our published usage examples of <code>ctf_sequence_text</code> show that the length provided should not include the null terminator.</p> LTTng-UST - Bug #1286 (Resolved): session daemon should validate credentials received from applic...https://bugs.lttng.org/issues/12862020-10-12T19:16:13ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>Looking at ustctl_recv_reg_msg() , I notice that the session daemon fails to validate the pid and uid credentials it receives from the application, thus trusting them blindly. This means a non-root application could theoretically impersonate a root application from a tracing perspective, and thus access root tracing buffers in a per-uid configuration, which is unwanted. I remember that initially we had no validation of the pid provided by the application because original lttng 2.0 only supported per-pid buffers and had per application tracing buffers only, so it did not cause any issue other than mislabeling the trace directory. However, now that the buffers can be shared between processes belonging to the same uid, this needs to be validated by the session daemon, and it's not.</p>
<p>So the quick fix here would be to validate on the session daemon side that the credentials provided by the application match those from a sessiond perspective through unix socket credentials (getsockopt(2) SO_PEERCRED on Linux and LOCAL_PEERCRED on BSD). That would however mean that sessiond would refuse applications that come from separate namespaces if the credentials don't match.</p>
<p>Tweaking liblttng-ust-comm/lttng-ust-comm.c:ustcomm_send_reg_msg() to send dummy credentials shows that the session daemon indeed trusts the application blindly.</p> LTTng-UST - Bug #1169 (Resolved): Possible race-condition in lttng-ust-statedump.c cleanup code d...https://bugs.lttng.org/issues/11692018-09-19T17:49:47ZRob Maher
<p>We have a short-lived program called 'testcmd' running on a Broadwell x86 processor with 8 logical cores (4 physical)<br />During cleanup/exit of the process while the system is under load (stress -c 6) we are seeing occasional core-dumps with similar traceback.</p>
<p>After inspecting the code it does not appear that there is locking within lttng-ust-statedump.c for the lttng_ust_statedump_destroy() function when it destroys the list. This patch seems to have resolved the issue for us.<br /><pre>
diff --git a/liblttng-ust/lttng-ust-statedump.c b/liblttng-ust/lttng-ust-statedump.c
index efa8a55..1b135de 100644
--- a/liblttng-ust/lttng-ust-statedump.c
+++ b/liblttng-ust/lttng-ust-statedump.c
@@ -630,6 +630,8 @@ void ust_dl_state_destroy(void)
{
unsigned int i;
+ ust_lock_nocheck();
+
for (i = 0; i < UST_DL_STATE_TABLE_SIZE; i++) {
struct cds_hlist_head *head;
struct lttng_ust_dl_node *e, *tmp;
@@ -639,6 +641,8 @@ void ust_dl_state_destroy(void)
free_dl_node(e);
CDS_INIT_HLIST_HEAD(head);
}
+
+ ust_unlock();
}
void lttng_ust_statedump_destroy(void)
--
2.1.1
</pre></p>
<p>Backtrace + some additional details are provided below. Please let me know if you need additional information.</p>
<pre>
#VERSION: This is using the source from the official lttng-ust 2.10.1 tarball.
#https://lttng.org/files/lttng-ust/lttng-ust-2.10.1.tar.bz2
# Here is the test program. Typically by the 40th iteration of the loop the program has crashed and dumped core at least once.
COUNTER=0; while [ 1 ]; do echo "ITER ${COUNTER}"; testcmd show c; ((COUNTER=COUNTER+1)); usleep 500000; done
# After setting the environment variable and re-running the above test, the program no longer crashes after >300 iterations.
export LTTNG_UST_DEBUG=1
### Here is the full backtrace of the threads present at the time of the core dump.
### This has been reproduced several times. As mentioned above, it usually happens by the 40th iteration.
Thread 3 (LWP 22540):
#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
No locals.
#1 0x000000344e21a246 in futex (val3=0, uaddr2=0x0, timeout=0x0, val=0, op=0, uaddr=<optimized out>) at /usr/include/urcu/futex.h:65
No locals.
#2 futex_async (op=0, val=0, timeout=0x0, uaddr2=0x0, val3=0, uaddr=<optimized out>) at /usr/include/urcu/futex.h:97
No locals.
#3 wait_for_sessiond (sock_info=0x344e4709e0 <local_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1311
No locals.
#4 ust_listener_thread (arg=0x344e4709e0 <local_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1373
sock_info = 0x344e4709e0 <local_apps>
sock = <optimized out>
ret = <optimized out>
prev_connect_failed = 1
has_waited = <optimized out>
timeout = <optimized out>
__func__ = "ust_listener_thread"
__PRETTY_FUNCTION__ = "ust_listener_thread"
#5 0x00000034460073e7 in start_thread (arg=0x7fcff3fde700) at /usr/src/debug/glibc/2.26-r0/git/nptl/pthread_create.c:465
pd = 0x7fcff3fde700
now = <optimized out>
unwind_buf = {
cancel_jmp_buf = {{
jmp_buf = {140531128461056, -6091954114337190402, 140734590213134, 140734590213135, 8396800, 140734590213312, 6118966899948899838, -6116587572263268866},
mask_was_saved = 0
}},
priv = {
pad = {0x0, 0x0, 0x0, 0x0},
data = {
prev = 0x0,
cleanup = 0x0,
canceltype = 0
}
}
}
not_first_call = <optimized out>
#6 0x00000034458f0bcf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.
Thread 2 (LWP 22538):
#0 __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
No locals.
#1 0x000000344587d204 in _int_free (av=0x3445baac20 <main_arena>, p=0x606160, have_lock=<optimized out>) at /usr/src/debug/glibc/2.26-r0/git/malloc/malloc.c:4273
size = 4192
fb = <optimized out>
nextchunk = <optimized out>
nextsize = <optimized out>
nextinuse = <optimized out>
prevsize = <optimized out>
bck = <optimized out>
fwd = <optimized out>
__func__ = "_int_free"
#2 0x000000344e22f2a1 in free_dl_node (e=0x606170) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:122
No locals.
#3 ust_dl_state_destroy () at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:639
e = 0x606170
tmp = 0x0
i = <optimized out>
#4 lttng_ust_statedump_destroy () at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:649
No locals.
#5 0x000000344e218f4b in lttng_ust_cleanup (exiting=1) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1815
No locals.
#6 0x000000344e20f077 in lttng_ust_exit () at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1874
ret = <optimized out>
__func__ = "lttng_ust_exit"
#7 0x000000344540f943 in _dl_fini () at /usr/src/debug/glibc/2.26-r0/git/elf/dl-fini.c:235
array = 0x344e469e60
i = <optimized out>
l = 0x7fcff47e4000
maps = 0x7fff5341dfa0
i = <optimized out>
l = <optimized out>
nmaps = <optimized out>
nloaded = <optimized out>
ns = 0
do_audit = <optimized out>
__PRETTY_FUNCTION__ = "_dl_fini"
#8 0x0000003445836608 in __run_exit_handlers (status=0, listp=0x3445baa6f8 <__exit_funcs>, run_list_atexit=run_list_atexit@entry=true, run_dtors=run_dtors@entry=true) at /usr/src/debug/glibc/2.26-r0/git/stdlib/exit.c:83
atfct = <optimized out>
onfct = <optimized out>
cxafct = <optimized out>
f = <optimized out>
#9 0x000000344583665a in __GI_exit (status=<optimized out>) at /usr/src/debug/glibc/2.26-r0/git/stdlib/exit.c:105
No locals.
#10 0x0000003445820f11 in __libc_start_main (main=0x400940 <main>, argc=3, argv=0x7fff5341e188, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff5341e178) at /usr/src/debug/glibc/2.26-r0/git/csu/libc-start.c:342
result = <optimized out>
unwind_buf = {
cancel_jmp_buf = {{
jmp_buf = {0, -6091953564717691394, 4197168, 140734590214528, 0, 0, 6092154793035550206, -6116588655236100610},
mask_was_saved = 0
}},
priv = {
pad = {0x0, 0x0, 0x7fff5341e1a8, 0x3445626110},
data = {
prev = 0x0,
cleanup = 0x0,
canceltype = 1396826536
}
}
}
not_first_call = <optimized out>
#11 0x0000000000400b5a in _start () at ../sysdeps/x86_64/start.S:120
No locals.
Thread 1 (LWP 22539):
#0 __GI_raise (sig=sig@entry=6) at /usr/src/debug/glibc/2.26-r0/git/sysdeps/unix/sysv/linux/raise.c:51
set = {
__val = {18446744067266838239, 18446744073709551615 <repeats 13 times>, 18446744067266838271, 0}
}
pid = <optimized out>
tid = <optimized out>
#1 0x0000003445835157 in __GI_abort () at /usr/src/debug/glibc/2.26-r0/git/stdlib/abort.c:90
save_stage = 2
act = {
__sigaction_handler = {
sa_handler = 0xffffffffffffffff,
sa_sigaction = 0xffffffffffffffff
},
sa_mask = {
__val = {18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744067266838271, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744067266838271, 140531136848272, 140531136848560}
},
sa_flags = -193076848,
sa_restorer = 0x1000
}
sigs = {
__val = {32, 0 <repeats 15 times>}
}
#2 0x00000034458751b8 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x34459750fc "%s\n") at /usr/src/debug/glibc/2.26-r0/git/sysdeps/posix/libc_fatal.c:181
ap = {{
gp_offset = 24,
fp_offset = 0,
overflow_arg_area = 0x7fcff47de2c0,
reg_save_area = 0x7fcff47de250
}}
fd = <optimized out>
list = <optimized out>
nlist = <optimized out>
cp = <optimized out>
written = <optimized out>
#3 0x000000344587b33a in malloc_printerr (str=str@entry=0x3445976d30 "double free or corruption (!prev)") at /usr/src/debug/glibc/2.26-r0/git/malloc/malloc.c:5368
No locals.
#4 0x000000344587cffc in _int_free (av=0x3445baac20 <main_arena>, p=0x610940, have_lock=<optimized out>) at /usr/src/debug/glibc/2.26-r0/git/malloc/malloc.c:4288
size = 4192
fb = <optimized out>
nextchunk = 0x6119a0
nextsize = <optimized out>
nextinuse = <optimized out>
prevsize = <optimized out>
bck = <optimized out>
fwd = <optimized out>
__func__ = "_int_free"
#5 0x000000344e22eb30 in free_dl_node (e=0x610950) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:122
No locals.
#6 iter_end (data=<optimized out>, ip=<optimized out>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:440
e = 0x610950
#7 lttng_ust_dl_update (ip=0x344e224429 <lttng_handle_pending_statedump+9>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:575
data = {
exec_found = 0,
first = false,
cancel = true
}
ip = 0x344e224429 <lttng_handle_pending_statedump+9>
#8 0x000000344e22f107 in do_baddr_statedump (owner=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:588
No locals.
#9 do_lttng_ust_statedump (owner=owner@entry=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:611
No locals.
#10 0x000000344e224429 in lttng_handle_pending_statedump (owner=owner@entry=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-events.c:871
session = <optimized out>
#11 0x000000344e21aa4d in handle_pending_statedump (sock_info=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:623
ctor_passed = 1
#12 handle_message (lum=0x7fcff47de8b0, sock=<optimized out>, sock_info=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:981
ret = <optimized out>
lur = {
handle = 0,
cmd = 68,
ret_code = 0,
ret_val = 0,
padding = '\000' <repeats 31 times>,
u = {
channel = {
memory_map_size = 0
},
stream = {
memory_map_size = 0
},
version = {
major = 0,
minor = 0,
patchlevel = 0
},
tracepoint = {
name = '\000' <repeats 255 times>,
loglevel = 0,
padding = '\000' <repeats 15 times>
},
padding = '\000' <repeats 31 times>
}
}
ctxstr = "\005", '\000' <repeats 254 times>
len = <optimized out>
ops = <optimized out>
args = {
channel = {
chan_data = 0x1500000014,
wakeup_fd = 5
},
stream = {
shm_fd = 20,
wakeup_fd = 21
},
field_list = {
entry = {
event_name = "\024\000\000\000\025\000\000\000\005", '\000' <repeats 246 times>,
field_name = '\000' <repeats 255 times>,
type = LTTNG_UST_FIELD_OTHER,
loglevel = 0,
nowrite = 0,
padding = '\000' <repeats 283 times>
}
},
app_context = {
ctxname = 0x1500000014 <error: Cannot access memory at address 0x1500000014>
}
}
#13 ust_listener_thread (arg=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1589
len = <optimized out>
lum = {
handle = 0,
cmd = 68,
padding = '\000' <repeats 31 times>,
u = {
channel = {
len = 0,
type = LTTNG_UST_CHAN_PER_CPU,
padding = '\000' <repeats 287 times>,
data = 0x7fcff47dea04 ""
},
stream = {
len = 0,
stream_nr = 0,
padding = '\000' <repeats 287 times>
},
event = {
instrumentation = LTTNG_UST_TRACEPOINT,
name = '\000' <repeats 255 times>,
loglevel_type = LTTNG_UST_LOGLEVEL_ALL,
loglevel = 0,
padding = '\000' <repeats 15 times>,
u = {
padding = '\000' <repeats 287 times>
}
},
context = {
ctx = LTTNG_UST_CONTEXT_VTID,
padding = '\000' <repeats 15 times>,
u = {
perf_counter = {
type = 0,
config = 0,
name = '\000' <repeats 255 times>
},
app_ctx = {
provider_name_len = 0,
ctx_name_len = 0
},
padding = '\000' <repeats 287 times>
}
},
version = {
major = 0,
minor = 0,
patchlevel = 0
},
tracepoint = {
name = '\000' <repeats 255 times>,
loglevel = 0,
padding = '\000' <repeats 15 times>
},
filter = {
data_size = 0,
reloc_offset = 0,
seqnum = 0
},
exclusion = {
count = 0
},
padding = '\000' <repeats 31 times>
}
}
sock_info = 0x344e472a20 <global_apps>
sock = <optimized out>
ret = <optimized out>
prev_connect_failed = 0
has_waited = <optimized out>
timeout = <optimized out>
__func__ = "ust_listener_thread"
__PRETTY_FUNCTION__ = "ust_listener_thread"
#14 0x00000034460073e7 in start_thread (arg=0x7fcff47df700) at /usr/src/debug/glibc/2.26-r0/git/nptl/pthread_create.c:465
pd = 0x7fcff47df700
now = <optimized out>
unwind_buf = {
cancel_jmp_buf = {{
jmp_buf = {140531136853760, -6091954114337190402, 140734590213134, 140734590213135, 8396800, 140734590213312, 6118950406737612286, -6116587572263268866},
mask_was_saved = 0
}},
priv = {
pad = {0x0, 0x0, 0x0, 0x0},
data = {
prev = 0x0,
cleanup = 0x0,
canceltype = 0
}
}
}
not_first_call = <optimized out>
#15 0x00000034458f0bcf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.
(gdb) thread apply all bt full
Thread 3 (LWP 22540):
#0 syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
No locals.
#1 0x000000344e21a246 in futex (val3=0, uaddr2=0x0, timeout=0x0, val=0, op=0, uaddr=<optimized out>) at /usr/include/urcu/futex.h:65
No locals.
#2 futex_async (op=0, val=0, timeout=0x0, uaddr2=0x0, val3=0, uaddr=<optimized out>) at /usr/include/urcu/futex.h:97
No locals.
#3 wait_for_sessiond (sock_info=0x344e4709e0 <local_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1311
No locals.
#4 ust_listener_thread (arg=0x344e4709e0 <local_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1373
sock_info = 0x344e4709e0 <local_apps>
sock = <optimized out>
ret = <optimized out>
prev_connect_failed = 1
has_waited = <optimized out>
timeout = <optimized out>
__func__ = "ust_listener_thread"
__PRETTY_FUNCTION__ = "ust_listener_thread"
#5 0x00000034460073e7 in start_thread (arg=0x7fcff3fde700) at /usr/src/debug/glibc/2.26-r0/git/nptl/pthread_create.c:465
pd = 0x7fcff3fde700
now = <optimized out>
unwind_buf = {
cancel_jmp_buf = {{
jmp_buf = {140531128461056, -6091954114337190402, 140734590213134, 140734590213135, 8396800, 140734590213312, 6118966899948899838, -6116587572263268866},
mask_was_saved = 0
}},
priv = {
pad = {0x0, 0x0, 0x0, 0x0},
data = {
prev = 0x0,
cleanup = 0x0,
canceltype = 0
}
}
}
not_first_call = <optimized out>
#6 0x00000034458f0bcf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.
Thread 2 (LWP 22538):
#0 __lll_lock_wait_private () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:95
No locals.
#1 0x000000344587d204 in _int_free (av=0x3445baac20 <main_arena>, p=0x606160, have_lock=<optimized out>) at /usr/src/debug/glibc/2.26-r0/git/malloc/malloc.c:4273
size = 4192
fb = <optimized out>
nextchunk = <optimized out>
nextsize = <optimized out>
nextinuse = <optimized out>
prevsize = <optimized out>
bck = <optimized out>
fwd = <optimized out>
__func__ = "_int_free"
#2 0x000000344e22f2a1 in free_dl_node (e=0x606170) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:122
No locals.
#3 ust_dl_state_destroy () at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:639
e = 0x606170
tmp = 0x0
i = <optimized out>
#4 lttng_ust_statedump_destroy () at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:649
No locals.
#5 0x000000344e218f4b in lttng_ust_cleanup (exiting=1) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1815
No locals.
#6 0x000000344e20f077 in lttng_ust_exit () at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1874
ret = <optimized out>
__func__ = "lttng_ust_exit"
#7 0x000000344540f943 in _dl_fini () at /usr/src/debug/glibc/2.26-r0/git/elf/dl-fini.c:235
array = 0x344e469e60
i = <optimized out>
l = 0x7fcff47e4000
maps = 0x7fff5341dfa0
i = <optimized out>
l = <optimized out>
nmaps = <optimized out>
nloaded = <optimized out>
ns = 0
do_audit = <optimized out>
__PRETTY_FUNCTION__ = "_dl_fini"
#8 0x0000003445836608 in __run_exit_handlers (status=0, listp=0x3445baa6f8 <__exit_funcs>, run_list_atexit=run_list_atexit@entry=true, run_dtors=run_dtors@entry=true) at /usr/src/debug/glibc/2.26-r0/git/stdlib/exit.c:83
atfct = <optimized out>
onfct = <optimized out>
cxafct = <optimized out>
f = <optimized out>
#9 0x000000344583665a in __GI_exit (status=<optimized out>) at /usr/src/debug/glibc/2.26-r0/git/stdlib/exit.c:105
No locals.
#10 0x0000003445820f11 in __libc_start_main (main=0x400940 <main>, argc=3, argv=0x7fff5341e188, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fff5341e178) at /usr/src/debug/glibc/2.26-r0/git/csu/libc-start.c:342
result = <optimized out>
unwind_buf = {
cancel_jmp_buf = {{
jmp_buf = {0, -6091953564717691394, 4197168, 140734590214528, 0, 0, 6092154793035550206, -6116588655236100610},
mask_was_saved = 0
}},
priv = {
pad = {0x0, 0x0, 0x7fff5341e1a8, 0x3445626110},
data = {
prev = 0x0,
cleanup = 0x0,
canceltype = 1396826536
}
}
}
not_first_call = <optimized out>
#11 0x0000000000400b5a in _start () at ../sysdeps/x86_64/start.S:120
No locals.
Thread 1 (LWP 22539):
#0 __GI_raise (sig=sig@entry=6) at /usr/src/debug/glibc/2.26-r0/git/sysdeps/unix/sysv/linux/raise.c:51
set = {
__val = {18446744067266838239, 18446744073709551615 <repeats 13 times>, 18446744067266838271, 0}
}
pid = <optimized out>
tid = <optimized out>
#1 0x0000003445835157 in __GI_abort () at /usr/src/debug/glibc/2.26-r0/git/stdlib/abort.c:90
save_stage = 2
act = {
__sigaction_handler = {
sa_handler = 0xffffffffffffffff,
sa_sigaction = 0xffffffffffffffff
},
sa_mask = {
__val = {18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744067266838271, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744073709551615, 18446744067266838271, 140531136848272, 140531136848560}
},
sa_flags = -193076848,
sa_restorer = 0x1000
}
sigs = {
__val = {32, 0 <repeats 15 times>}
}
#2 0x00000034458751b8 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x34459750fc "%s\n") at /usr/src/debug/glibc/2.26-r0/git/sysdeps/posix/libc_fatal.c:181
ap = {{
gp_offset = 24,
fp_offset = 0,
overflow_arg_area = 0x7fcff47de2c0,
reg_save_area = 0x7fcff47de250
}}
fd = <optimized out>
list = <optimized out>
nlist = <optimized out>
cp = <optimized out>
written = <optimized out>
#3 0x000000344587b33a in malloc_printerr (str=str@entry=0x3445976d30 "double free or corruption (!prev)") at /usr/src/debug/glibc/2.26-r0/git/malloc/malloc.c:5368
No locals.
#4 0x000000344587cffc in _int_free (av=0x3445baac20 <main_arena>, p=0x610940, have_lock=<optimized out>) at /usr/src/debug/glibc/2.26-r0/git/malloc/malloc.c:4288
size = 4192
fb = <optimized out>
nextchunk = 0x6119a0
nextsize = <optimized out>
nextinuse = <optimized out>
prevsize = <optimized out>
bck = <optimized out>
fwd = <optimized out>
__func__ = "_int_free"
#5 0x000000344e22eb30 in free_dl_node (e=0x610950) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:122
No locals.
#6 iter_end (data=<optimized out>, ip=<optimized out>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:440
e = 0x610950
#7 lttng_ust_dl_update (ip=0x344e224429 <lttng_handle_pending_statedump+9>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:575
data = {
exec_found = 0,
first = false,
cancel = true
}
ip = 0x344e224429 <lttng_handle_pending_statedump+9>
#8 0x000000344e22f107 in do_baddr_statedump (owner=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:588
No locals.
#9 do_lttng_ust_statedump (owner=owner@entry=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-statedump.c:611
No locals.
#10 0x000000344e224429 in lttng_handle_pending_statedump (owner=owner@entry=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-events.c:871
session = <optimized out>
#11 0x000000344e21aa4d in handle_pending_statedump (sock_info=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:623
ctor_passed = 1
#12 handle_message (lum=0x7fcff47de8b0, sock=<optimized out>, sock_info=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:981
ret = <optimized out>
lur = {
handle = 0,
cmd = 68,
ret_code = 0,
ret_val = 0,
padding = '\000' <repeats 31 times>,
u = {
channel = {
memory_map_size = 0
},
stream = {
memory_map_size = 0
},
version = {
major = 0,
minor = 0,
patchlevel = 0
},
tracepoint = {
name = '\000' <repeats 255 times>,
loglevel = 0,
padding = '\000' <repeats 15 times>
},
padding = '\000' <repeats 31 times>
}
}
ctxstr = "\005", '\000' <repeats 254 times>
len = <optimized out>
ops = <optimized out>
args = {
channel = {
chan_data = 0x1500000014,
wakeup_fd = 5
},
stream = {
shm_fd = 20,
wakeup_fd = 21
},
field_list = {
entry = {
event_name = "\024\000\000\000\025\000\000\000\005", '\000' <repeats 246 times>,
field_name = '\000' <repeats 255 times>,
type = LTTNG_UST_FIELD_OTHER,
loglevel = 0,
nowrite = 0,
padding = '\000' <repeats 283 times>
}
},
app_context = {
ctxname = 0x1500000014 <error: Cannot access memory at address 0x1500000014>
}
}
#13 ust_listener_thread (arg=0x344e472a20 <global_apps>) at /usr/src/debug/lttng-ust/2_2.10.1-r0/lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1589
len = <optimized out>
lum = {
handle = 0,
cmd = 68,
padding = '\000' <repeats 31 times>,
u = {
channel = {
len = 0,
type = LTTNG_UST_CHAN_PER_CPU,
padding = '\000' <repeats 287 times>,
data = 0x7fcff47dea04 ""
},
stream = {
len = 0,
stream_nr = 0,
padding = '\000' <repeats 287 times>
},
event = {
instrumentation = LTTNG_UST_TRACEPOINT,
name = '\000' <repeats 255 times>,
loglevel_type = LTTNG_UST_LOGLEVEL_ALL,
loglevel = 0,
padding = '\000' <repeats 15 times>,
u = {
padding = '\000' <repeats 287 times>
}
},
context = {
ctx = LTTNG_UST_CONTEXT_VTID,
padding = '\000' <repeats 15 times>,
u = {
perf_counter = {
type = 0,
config = 0,
name = '\000' <repeats 255 times>
},
app_ctx = {
provider_name_len = 0,
ctx_name_len = 0
},
padding = '\000' <repeats 287 times>
}
},
version = {
major = 0,
minor = 0,
patchlevel = 0
},
tracepoint = {
name = '\000' <repeats 255 times>,
loglevel = 0,
padding = '\000' <repeats 15 times>
},
filter = {
data_size = 0,
reloc_offset = 0,
seqnum = 0
},
exclusion = {
count = 0
},
padding = '\000' <repeats 31 times>
}
}
sock_info = 0x344e472a20 <global_apps>
sock = <optimized out>
ret = <optimized out>
prev_connect_failed = 0
has_waited = <optimized out>
timeout = <optimized out>
__func__ = "ust_listener_thread"
__PRETTY_FUNCTION__ = "ust_listener_thread"
#14 0x00000034460073e7 in start_thread (arg=0x7fcff47df700) at /usr/src/debug/glibc/2.26-r0/git/nptl/pthread_create.c:465
pd = 0x7fcff47df700
now = <optimized out>
unwind_buf = {
cancel_jmp_buf = {{
jmp_buf = {140531136853760, -6091954114337190402, 140734590213134, 140734590213135, 8396800, 140734590213312, 6118950406737612286, -6116587572263268866},
mask_was_saved = 0
}},
priv = {
pad = {0x0, 0x0, 0x0, 0x0},
data = {
prev = 0x0,
cleanup = 0x0,
canceltype = 0
}
}
}
not_first_call = <optimized out>
#15 0x00000034458f0bcf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
No locals.
(gdb)
</pre>
<pre>
### This is the output of a single execution of the above command with LTTNG_UST_DEBUG environment variable set.
### (Program does not crash and exits normally.)
root@hal-dnx:/# testcmd show c
liblttng_ust_tracepoint[6722/6722]: Your compiler treats weak symbols with hidden visibility for integer objects as SAME address between compile units part of the same module. (in check_weak_hidden() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:916)
liblttng_ust_tracepoint[6722/6722]: Your compiler treats weak symbols with hidden visibility for pointer objects as SAME address between compile units part of the same module. (in check_weak_hidden() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:920)
liblttng_ust_tracepoint[6722/6722]: Your compiler treats weak symbols with hidden visibility for 24-byte structure objects as SAME address between compile units part of the same module. (in check_weak_hidden() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:924)
liblttng_ust_tracepoint[6722/6722]: just registered a tracepoints section from 0x344e4751e0 and having 25 tracepoints (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:867)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_statedump:end (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_statedump:debug_link (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_statedump:build_id (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_statedump:bin_info (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_statedump:start (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_lib:unload (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_lib:debug_link (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_lib:build_id (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_lib:load (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracef:event (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_LINE (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_FUNCTION (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_UNIT (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_MODULE (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_PROCESS (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_PROGRAM (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_DEBUG_SYSTEM (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_INFO (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_NOTICE (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_WARNING (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_ERR (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_CRIT (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_ALERT (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
liblttng_ust_tracepoint[6722/6722]: registered tracepoint: lttng_ust_tracelog:TRACE_EMERG (in tracepoint_register_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:872)
libust[6722/6722]: Provider "lttng_ust_statedump" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: adding probe lttng_ust_statedump containing 5 events to lazy registration list (in lttng_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:219)
libust[6722/6722]: LTT : ltt ring buffer client "relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-metadata-client.h:350)
libust[6722/6722]: LTT : ltt ring buffer client "relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:825)
libust[6722/6722]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:825)
libust[6722/6722]: LTT : ltt ring buffer client "relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:825)
libust[6722/6722]: LTT : ltt ring buffer client "relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:825)
libust[6722/6724]: Info: sessiond not accepting connections to local apps socket (in ust_listener_thread() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1424)
libust[6722/6724]: Waiting for local apps sessiond (in wait_for_sessiond() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:1306)
libust[6722/6723]: Message Received "Get Tracer Version" (65), Handle "root" (0) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Session" (64), Handle "root" (0) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 1 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Channel" (81), Handle "session" (1) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: channel data received (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:811)
libust[6722/6723]: Return value: 2 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Stream" (96), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 3 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (3) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 4 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (4) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 5 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (5) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 6 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (6) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 7 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (7) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 8 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (8) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 9 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (9) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 10 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (10) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 11 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (11) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 12 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (12) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 13 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (13) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 14 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (14) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 15 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (15) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 16 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (16) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 17 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (17) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 18 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (18) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 19 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (19) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 20 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (20) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 21 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (21) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 22 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (22) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 23 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (23) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Create Event" (97), Handle "channel" (2) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 24 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "enabler" (24) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Enable" (128), Handle "session" (1) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Sent register channel notification: chan_id 0, header_type 1
(in ustcomm_register_channel() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1511)
libust[6722/6723]: just registered probe lttng_ust_statedump containing 5 events (in lttng_lazy_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:116)
liblttng_ust_tracepoint[6722/6723]: Release queue of unregistered tracepoint probes. (in __tracepoint_probe_prune_release_queue() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:702)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Wait for Quiescent State" (67), Handle "root" (0) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6723]: message successfully sent (in send_reply() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:571)
libust[6722/6723]: Message Received "Registration Done" (68), Handle "root" (0) (in print_cmd() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:430)
libust[6722/6722]: Provider "lttng_ust_lib" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6723]: Return value: 0 (in handle_message() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ust-comm.c:972)
libust[6722/6722]: adding probe lttng_ust_lib containing 4 events to lazy registration list (in lttng_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:219)
libust[6722/6722]: just registered probe lttng_ust_lib containing 4 events (in lttng_lazy_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:116)
liblttng_ust_tracepoint[6722/6722]: Release queue of unregistered tracepoint probes. (in __tracepoint_probe_prune_release_queue() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:702)
libust[6722/6722]: Provider "lttng_ust_tracef" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: adding probe lttng_ust_tracef containing 1 events to lazy registration list (in lttng_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:219)
libust[6722/6722]: just registered probe lttng_ust_tracef containing 1 events (in lttng_lazy_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:116)
liblttng_ust_tracepoint[6722/6722]: Release queue of unregistered tracepoint probes. (in __tracepoint_probe_prune_release_queue() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:702)
libust[6722/6722]: Provider "lttng_ust_tracelog" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: adding probe lttng_ust_tracelog containing 15 events to lazy registration list (in lttng_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:219)
libust[6722/6722]: just registered probe lttng_ust_tracelog containing 15 events (in lttng_lazy_probe_register() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:116)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_EMERG": ret_code 0, event_id 0
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_ALERT": ret_code 0, event_id 1
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_CRIT": ret_code 0, event_id 2
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_ERR": ret_code 0, event_id 3
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_WARNING": ret_code 0, event_id 4
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_NOTICE": ret_code 0, event_id 5
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
libust[6722/6722]: Sent register event notification for name "lttng_ust_tracelog:TRACE_INFO": ret_code 0, event_id 6
(in ustcomm_register_event() at ../../lttng-ust-2.10.1/liblttng-ust-comm/lttng-ust-comm.c:1293)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_INFO. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_NOTICE. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_WARNING. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_ERR. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_CRIT. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_ALERT. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Registering probe to tracepoint lttng_ust_tracelog:TRACE_EMERG. Queuing release. (in __tracepoint_probe_register_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:611)
liblttng_ust_tracepoint[6722/6722]: Release queue of unregistered tracepoint probes. (in __tracepoint_probe_prune_release_queue() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:702)
libust[6722/6722]: Provider "lttng_ust_tracelog" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: just unregistered probe lttng_ust_tracelog (in lttng_probe_unregister() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:250)
libust[6722/6722]: Provider "lttng_ust_tracef" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: just unregistered probe lttng_ust_tracef (in lttng_probe_unregister() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:250)
libust[6722/6722]: Provider "lttng_ust_lib" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: just unregistered probe lttng_ust_lib (in lttng_probe_unregister() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:250)
|liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_INFO. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_NOTICE. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_WARNING. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_ERR. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_CRIT. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_ALERT. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Un-registering probe from tracepoint lttng_ust_tracelog:TRACE_EMERG. Queuing release. (in __tracepoint_probe_unregister_queue_release() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:682)
liblttng_ust_tracepoint[6722/6722]: Release queue of unregistered tracepoint probes. (in __tracepoint_probe_prune_release_queue() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:702)
libust[6722/6722]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:832)
libust[6722/6722]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:832)
libust[6722/6722]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:832)
libust[6722/6722]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-client.h:832)
libust[6722/6722]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-ring-buffer-metadata-client.h:357)
libust[6722/6722]: Provider "lttng_ust_statedump" accepted, version 1.0 is compatible with LTTng UST provider version 1.0. (in check_provider_version() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:175)
libust[6722/6722]: just unregistered probe lttng_ust_statedump (in lttng_probe_unregister() at ../../lttng-ust-2.10.1/liblttng-ust/lttng-probes.c:250)
liblttng_ust_tracepoint[6722/6722]: just unregistered a tracepoints section from 0x344e4751e0 (in tracepoint_unregister_lib() at ../../lttng-ust-2.10.1/liblttng-ust/tracepoint.c:897)
root@hal-dnx:/#
root@hal-dnx:/#
</pre> LTTng-UST - Bug #1064 (Resolved): Deadlock while dlopen-ing a providerhttps://bugs.lttng.org/issues/10642016-10-01T00:49:35ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>I have been observing spurious deadlocks in the <a href="https://github.com/lttng/lttng-tools/tree/master/tests/regression/ust/ust-dl" class="external">ust-dl</a> test on the LTTng CI.</p>
<p>I finally managed to capture a backtrace which helps understand the problem:<br /><pre>
(gdb) thread apply all bt
Thread 3 (Thread 0xf6c4fb40 (LWP 712439)):
#0 0xf76eebe9 in __kernel_vsyscall ()
#1 0xf76bfd32 in __lll_lock_wait () at ../sysdeps/unix/sysv/linux/i386/lowlevellock.S:144
#2 0xf76b9939 in __GI___pthread_mutex_lock (mutex=0xf77134e4 <_rtld_global+1220>) at ../nptl/pthread_mutex_lock.c:115
#3 0xf7700828 in tls_get_addr_tail (ti=0xf74eff24, dtv=0x9c858b8, the_map=0xf74fa198) at dl-tls.c:765
#4 0xf74addfc in _rcu_read_lock_bp () at /home/jenkins/workspace/lttng-ust_master_build/arch/x86-32/build/std/conf/std/liburcu_version/master/deps/liburcu/build/include/urcu/static/urcu-bp.h:168
#5 __tracepoint_cb_lttng_ust_statedump___start (session=0xf6300498) at lttng-ust-statedump-provider.h:41
#6 trace_start_cb (session=0xf6300498, priv=0x0) at lttng-ust-statedump.c:251
#7 0xf74ac836 in trace_statedump_event (tp_cb=tp_cb@entry=0xf74addd0 <trace_start_cb>, owner=owner@entry=0xf74f04e0 <local_apps>, priv=priv@entry=0x0) at lttng-ust-statedump.c:212
#8 0xf74ae7ea in trace_statedump_start (owner=0xf74f04e0 <local_apps>) at lttng-ust-statedump.c:347
#9 do_lttng_ust_statedump (owner=0xf74f04e0 <local_apps>) at lttng-ust-statedump.c:601
#10 0xf74a383a in lttng_handle_pending_statedump (owner=0xf74f04e0 <local_apps>) at lttng-events.c:869
#11 0xf7498ece in handle_pending_statedump (sock_info=<optimized out>) at lttng-ust-comm.c:589
#12 handle_message (lum=0xf6c4ea80, sock=<optimized out>, sock_info=<optimized out>) at lttng-ust-comm.c:974
#13 ust_listener_thread (arg=0xf74f04e0 <local_apps>) at lttng-ust-comm.c:1507
#14 0xf76b72b5 in start_thread (arg=0xf6c4fb40) at pthread_create.c:333
#15 0xf75e216e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:114
Thread 2 (Thread 0xf7450b40 (LWP 712438)):
#0 0xf76eebe9 in __kernel_vsyscall ()
#1 0xf75ddbb7 in syscall () at ../sysdeps/unix/sysv/linux/i386/syscall.S:29
#2 0xf74990b2 in futex (val3=0, uaddr2=0x0, timeout=0x0, val=0, op=0, uaddr=<optimized out>) at /home/jenkins/workspace/lttng-ust_master_build/arch/x86-32/build/std/conf/std/liburcu_version/master/deps/liburcu/build/include/urcu/futex.h:65
#3 futex_async (op=0, val=0, timeout=0x0, uaddr2=0x0, val3=0, uaddr=<optimized out>) at /home/jenkins/workspace/lttng-ust_master_build/arch/x86-32/build/std/conf/std/liburcu_version/master/deps/liburcu/build/include/urcu/futex.h:97
#4 wait_for_sessiond (sock_info=<optimized out>) at lttng-ust-comm.c:1258
#5 ust_listener_thread (arg=0xf74f2520 <global_apps>) at lttng-ust-comm.c:1319
#6 0xf76b72b5 in start_thread (arg=0xf7450b40) at pthread_create.c:333
#7 0xf75e216e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:114
Thread 1 (Thread 0xf7451740 (LWP 712437)):
#0 0xf76eebe9 in __kernel_vsyscall ()
#1 0xf76bfd32 in __lll_lock_wait () at ../sysdeps/unix/sysv/linux/i386/lowlevellock.S:144
#2 0xf76b98be in __GI___pthread_mutex_lock (mutex=0xf74f5038 <ust_mutex>) at ../nptl/pthread_mutex_lock.c:80
#3 0xf7497e27 in ust_lock () at lttng-ust-comm.c:140
#4 0xf74ad547 in iter_begin (data=0xff88cb54) at lttng-ust-statedump.c:368
#5 0xf74adce8 in extract_bin_info_events (info=0xff88cab8, size=40, _data=0xff88cb54) at lttng-ust-statedump.c:453
#6 0xf7617afe in __GI___dl_iterate_phdr (callback=0xf74adca0 <extract_bin_info_events>, data=0xff88cb54) at dl-iteratephdr.c:76
#7 0xf74ae1da in lttng_ust_dl_update (ip=0xf76d4a03 <__tracepoints__init+114>) at lttng-ust-statedump.c:565
#8 0xf76e3597 in dlopen (filename=0xf76d4e08 "liblttng-ust-tracepoint.so.0", flags=258) at lttng-ust-dl.c:222
#9 0xf76d4a03 in __tracepoints__init () at /home/jenkins/workspace/dev_jgalar_lttng-tools_master-staging_build/arch/x86-32/babeltrace_version/master/build/oot/conf/python-bindings/liburcu_version/master/deps/lttng-ust/build/include/lttng/tracepoint.h:321
#10 0xf76fe365 in call_init (l=<optimized out>, argc=argc@entry=1, argv=argv@entry=0xff88d0d4, env=0xff88d0dc) at dl-init.c:72
#11 0xf76fe48e in call_init (env=0xff88d0dc, argv=0xff88d0d4, argc=1, l=<optimized out>) at dl-init.c:30
#12 _dl_init (main_map=main_map@entry=0x9c86d68, argc=1, argv=0xff88d0d4, env=0xff88d0dc) at dl-init.c:120
#13 0xf770275a in dl_open_worker (a=0xff88cdec) at dl-open.c:575
#14 0xf76fe204 in _dl_catch_error (objname=objname@entry=0xff88cde4, errstring=errstring@entry=0xff88cde8, mallocedp=mallocedp@entry=0xff88cde3, operate=0xf7702370 <dl_open_worker>, args=0xff88cdec) at dl-error.c:187
#15 0xf7701f02 in _dl_open (file=0x8048860 "libbar.so", mode=-2147483647, caller_dlopen=0xf76e354a <dlopen+58>, nsid=<optimized out>, argc=1, argv=0xff88d0d4, env=0xff88d0dc) at dl-open.c:660
#16 0xf76cf8bd in dlopen_doit (a=0xff88cfa0) at dlopenold.c:54
#17 0xf76fe204 in _dl_catch_error (objname=0x9c79014, errstring=0x9c79018, mallocedp=0x9c79010, operate=0xf76cf850 <dlopen_doit>, args=0xff88cfa0) at dl-error.c:187
#18 0xf76cf30d in _dlerror_run (operate=operate@entry=0xf76cf850 <dlopen_doit>, args=args@entry=0xff88cfa0) at dlerror.c:163
#19 0xf76cf939 in __dlopen_nocheck (file=0x8048860 "libbar.so", mode=1) at dlopenold.c:76
#20 0xf76e354a in _lttng_ust_dl_libc_dlopen (flags=1, filename=0x8048860 "libbar.so") at lttng-ust-dl.c:55
#21 dlopen (filename=0x8048860 "libbar.so", flags=1) at lttng-ust-dl.c:211
#22 0x0804866b in main (argc=1, argv=0xff88d0d4) at /home/jenkins/workspace/dev_jgalar_lttng-tools_master-staging_build/arch/x86-32/babeltrace_version/master/build/oot/conf/python-bindings/liburcu_version/master/tests/regression/ust/ust-dl/prog.c:20
</pre></p>
<p>We can see that:</p>
<p><strong>Thread 1</strong> has acquired the glibc dynamic loader lock (by dlopening a provider, libbar.so).<br /><strong>Thread 1</strong> is trying to acquire ust_lock in <em>extract_bin_info_events()</em>.</p>
<p><strong>Thread 3</strong> has acquired the ust_lock (taken in <em>handle_message()</em>).<br /><strong>Thread 3</strong> then triggers a tracepoint in <em>trace_start_cb()</em>, which calls into _<em>rcu_read_lock_bp()</em>, accessing/faulting a TLS which causes a call into <em>tls_get_addr_tail()</em>, causing the thread to try to acquire the glibc dynamic loader lock.</p>
<p>Therefore, it is easy to make the problem reproducible by making the following modification to lttng-ust:<br /><pre>
diff --git a/liblttng-ust/lttng-ust-statedump.c b/liblttng-ust/lttng-ust-statedump.c
index 644af30..e372bc2 100644
--- a/liblttng-ust/lttng-ust-statedump.c
+++ b/liblttng-ust/lttng-ust-statedump.c
@@ -365,6 +365,7 @@ void iter_begin(struct dl_iterate_data *data)
* protect memory allocation at early process start, due to
* interactions with libc-wrapper lttng malloc instrumentation.
*/
+ sleep(1);
if (ust_lock()) {
data->cancel = true;
return;
</pre></p> LTTng - Feature #968 (Feedback): lttng-modules kernel and user callstack contexthttps://bugs.lttng.org/issues/9682015-10-25T20:14:40ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>Implementation from Francis Giraldeau reviewed and cleaned up available here:</p>
<p><a class="external" href="https://github.com/compudj/lttng-tools-dev/tree/callstack">https://github.com/compudj/lttng-tools-dev/tree/callstack</a><br /><a class="external" href="https://github.com/compudj/lttng-modules-dev/tree/callstack">https://github.com/compudj/lttng-modules-dev/tree/callstack</a></p>
<p>Documentation and tests are missing.</p> LTTng - Feature #966 (Resolved): Merge Java early filtering featurehttps://bugs.lttng.org/issues/9662015-10-22T20:47:44ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>UST: <a class="external" href="https://github.com/alexmonthy/lttng-ust/commits/java-filter-notifications">https://github.com/alexmonthy/lttng-ust/commits/java-filter-notifications</a></p>
<p>Tools: <a class="external" href="https://github.com/alexmonthy/lttng-tools/tree/java-filter-notifications">https://github.com/alexmonthy/lttng-tools/tree/java-filter-notifications</a></p>
<p>Needs to be merged in both projects in locked-step.</p> LTTng-UST - Feature #965 (New): Implement UST statedumphttps://bugs.lttng.org/issues/9652015-10-22T20:43:37ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>Initial implementation: <a class="external" href="https://github.com/compudj/lttng-ust-dev/tree/statedump-notifier">https://github.com/compudj/lttng-ust-dev/tree/statedump-notifier</a></p>
<p>Missing tests in lttng-tools for this feature before we can merge it into lttng-ust.</p> LTTng-tools - Bug #902 (Invalid): Crash on consumer daemon due to double free or corruptionhttps://bugs.lttng.org/issues/9022015-08-06T16:00:39Zanusha mahamkalianujntu93@gmail.com
<p>We have observed crash on consumer daemon, during repetitive restarts of our trace generating system (target).<br />Crash is observed during the startup of the system. Reason for the crash is "double free or corruption (out)".</p>
<p>Below is the call trace from the core dump generated:<br />#0 0x000000804ce20000 in __GI_raise (sig=<optimized out>) at ../sysdeps/unix/sysv/linux/raise.c:55<br />#1 0x000000804ce25850 in __GI_abort () at abort.c:89<br />#2 0x000000804ce60e24 in __libc_message (do_abort=<optimized out>, fmt=<optimized out>) at ../sysdeps/posix/libc_fatal.c:175<br />#3 0x000000804ce6f368 in malloc_printerr (action=<optimized out>, str=0x804cf4f220 "double free or corruption (out)", ptr=<optimized out>) at malloc.c:4958<br />#4 0x000000804ce701bc in _int_free (av=<optimized out>, p=<optimized out>, have_lock=<optimized out>) at malloc.c:3829<br />#5 0x0000000010011ab8 in ?? ()</p>
<p>Currently we are using LTTng tools version 2.6.<br />Can you please let us know if you have observed any similar issue like above?</p> LTTng-tools - Bug #861 (Resolved): UST subbuffers silently dropped on moderate trace traffichttps://bugs.lttng.org/issues/8612014-11-18T16:31:15ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>lttng-tools commit 02b3d1769d5f8a33e4109b1e681141c9295dfda6 introduced an important regression for lttng-ust tracing in the consumer daemon: after reading a sub-buffer, a check has been added to see whether there are more sub-buffers available to read, and if it is the case, it ensures the wakeup pipe will be awakened again.</p>
<p>The issue lies in the use of ustctl_put_next_subbuf() in this check. This acts as if the sub-buffer has been read, when in reality it has not been read. It therefore trashes the data contained by this sub-buffer.</p>
<p>This check should use ustctl_put_subbuf(), which does not move the consumer position.</p> LTTng-UST - Bug #745 (Resolved): base address dump triggers deadlockshttps://bugs.lttng.org/issues/7452014-02-27T21:24:18ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>It appears that the daemon() test case of lttng-tools deadlocks when base address is dumped.<br />(lttng-tools tests/regression/ust/daemon)</p>
<p>From preliminary analysis, it seems to be a hang in the child process, likely caused by use of the dynamic linker lock within a lttng-ust thread without protection of ust_lock().</p>
<p>We'll need to figure out a way to rework locking to make use of the dynamic linked safe wrt fork/clone/daemon. It's possible that we need to disable the base address feature for 2.4, as it is late in the rc cycle.</p> LTTng-modules - Bug #631 (Resolved): hard lockup with lttng-modules and kernel 3.10 +https://bugs.lttng.org/issues/6312013-09-11T16:13:45ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>Starting from Linux kernel commit<br />06c017fdd4dc48451a29ac37fc1db4a3f86b7f40 "timekeeping: Hold<br />timekeepering locks in do_adjtimex and hardpps" (3.10 kernels), the<br />xtime write seqlock is held across calls to __do_adjtimex(), which<br />includes a call to notify_cmos_timer(), and hence<br />schedule_delayed_work().</p>
<p>This introduces a side-effect for a set of tracepoints, including mainly<br />the workqueue tracepoints: a tracer hooking on those tracepoints and<br />reading current time with ktime_get() will cause hard system LOCKUP such<br />as:</p>
<pre>
WARNING: CPU: 6 PID: 2258 at kernel/watchdog.c:245 watchdog_overflow_callback+0x93/0x9e()
Watchdog detected hard LOCKUP on cpu 6
Modules linked in: lttng_probe_workqueue(O) lttng_probe_vmscan(O) lttng_probe_udp(O) lttng_probe_timer(O) lttng_probe_s]
CPU: 6 PID: 2258 Comm: ntpd Tainted: G O 3.11.0 #158
Hardware name: Supermicro X7DAL/X7DAL, BIOS 6.00 12/03/2007
0000000000000000 ffffffff814f83eb ffffffff813b206a ffff88042fd87c78
ffffffff8106a07c 0000000000000000 ffffffff810c94c2 0000000000000000
ffff88041f31bc00 0000000000000000 ffff88042fd87d68 ffff88042fd87ef8
Call Trace:
<NMI> [<ffffffff813b206a>] ? dump_stack+0x41/0x51
[<ffffffff8106a07c>] ? warn_slowpath_common+0x79/0x92
[<ffffffff810c94c2>] ? watchdog_overflow_callback+0x93/0x9e
[<ffffffff8106a12d>] ? warn_slowpath_fmt+0x45/0x4a
[<ffffffff810c94c2>] ? watchdog_overflow_callback+0x93/0x9e
[<ffffffff810c942f>] ? watchdog_enable_all_cpus.part.2+0x31/0x31
[<ffffffff810ecc66>] ? __perf_event_overflow+0x12c/0x1ae
[<ffffffff810eab60>] ? perf_event_update_userpage+0x13/0xc2
[<ffffffff81016820>] ? intel_pmu_handle_irq+0x26a/0x2fd
[<ffffffff813b7a0b>] ? perf_event_nmi_handler+0x24/0x3d
[<ffffffff813b728f>] ? nmi_handle.isra.3+0x58/0x12f
[<ffffffff813b7a59>] ? perf_ibs_nmi_handler+0x35/0x35
[<ffffffff813b7404>] ? do_nmi+0x9e/0x2bc
[<ffffffff813b6af7>] ? end_repeat_nmi+0x1e/0x2e
[<ffffffff810a2a33>] ? read_seqcount_begin.constprop.4+0x8/0xf
[<ffffffff810a2a33>] ? read_seqcount_begin.constprop.4+0x8/0xf
[<ffffffff810a2a33>] ? read_seqcount_begin.constprop.4+0x8/0xf
<<EOE>> [<ffffffff810a2d6c>] ? ktime_get+0x23/0x5e
[<ffffffffa0314670>] ? lib_ring_buffer_clock_read.isra.28+0x1f/0x21 [lttng_ring_buffer_client_discard]
[<ffffffffa0314786>] ? lttng_event_reserve+0x112/0x3f3 [lttng_ring_buffer_client_discard]
[<ffffffffa045b1c5>] ? __event_probe__workqueue_queue_work+0x72/0xe0 [lttng_probe_workqueue]
[<ffffffff812ef7e9>] ? sock_aio_read.part.10+0x110/0x124
[<ffffffff81133a36>] ? do_sync_readv_writev+0x50/0x76
[<ffffffff8107d514>] ? __queue_work+0x1ab/0x265
[<ffffffff8107da7e>] ? queue_delayed_work_on+0x3f/0x4e
[<ffffffff810a473d>] ? __do_adjtimex+0x408/0x413
[<ffffffff810a3e9a>] ? do_adjtimex+0x98/0xee
[<ffffffff8106cec6>] ? SYSC_adjtimex+0x32/0x5d
[<ffffffff813bb74b>] ? tracesys+0xdd/0xe2
</pre> LTTng-UST - Bug #487 (Resolved): Per UID buffer: Can not see any data being loggedhttps://bugs.lttng.org/issues/4872013-03-27T15:46:11ZTan le trantan.dung.le.tran@ericsson.com
<pre>
Problem Description:
====================
* After the session is activated and instrumented app launched, no
log can be obtained. Only metadata file contain "seem to be valid" data.
Babeltrace the session directory gives nothing.
Is problem reproducible ?
=========================
* yes 100%
How to reproduce (if reproducible):
===================================
1)_
export TC=ses1
ps -ef |egrep 'lttng'
netstat -etanp | head -n 2 ; netstat -etanp |egrep lttng
lttng-relayd -C tcp://0.0.0.0:53000 -D tcp://0.0.0.0:53001 -o /cluster/temp/log/$TC &
netstat -etanp | head -n 2 ; netstat -etanp |egrep lttng
time lttng list
time lttng create $TC -U net://192.168.0.1:53000:53001/./
time lttng list
sleep 1
time lttng enable-channel -u --buffers-uid chan1
sleep 1
time lttng enable-event -s $TC "com*" -u -c chan1
sleep 1
time lttng list $TC
sleep 1
time lttng start;
sleep 1
time lttng list
2)_ Launch the application
/home/test_apps/TestApp_type1 50000 np &
lttng list -u
#-- shows that the instr app has registered and sessionD sees all their tracepoints
# all tracepoints start with com_....
3)_ dir ses1/SC-1/ust/uid/0/64-bit/ (current directory is : /cluster/temp/log/)
total 0
-rwxr-xr-x 1 root root 0 Mar 26 17:54 metadata
-rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_3
-rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_2
-rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_1
-rwxr-xr-x 1 root root 0 Mar 26 17:54 chan1_0
Repeat the above command again and again, but still see all filesize 0.
The above instr app should produce about 10000 events per sec, and
we are expecting to get about 600KB/s of data.
4)_ lttng stop
lttng destroy
pkill relayd
5)_ dir ses1/SC-1/ust/uid/0/64-bit/
total 44
-rwxr-xr-x 1 root root 12288 Mar 26 17:55 metadata
-rwxr-xr-x 1 root root 8192 Mar 26 17:55 chan1_3
-rwxr-xr-x 1 root root 8192 Mar 26 17:55 chan1_2
-rwxr-xr-x 1 root root 8192 Mar 26 17:55 chan1_1
-rwxr-xr-x 1 root root 8192 Mar 26 17:55 chan1_0
6)_ more ses1/SC-1/ust/uid/0/64-bit/metadata #-- shows that the tracepoints are present
7)_ babeltrace ses1/SC-1/ust/uid/0/64-bit/
babeltrace ses1/SC-1/ust/uid/0/64-bit/
babeltrace ses1/SC-1/ust/uid/0/
babeltrace ses1/SC-1/ust/
babeltrace ses1/SC-1/
babeltrace ses1/
#--- get nothing in printout
Commit used:
============
userspace : d107390 (HEAD, origin/master, origin/HEAD, globalBuffer) Add tab to output in ...
lttng-ust : e2ad3b4 (HEAD, origin/master, origin/HEAD, globalBuffer) Add demo README
lttng-tools : 9f9ee9c (HEAD, origin/master, origin/HEAD, globalBuffer) Fix: UST context activation
babeltrace : c99b191 (HEAD, tag: v1.1.0) Version 1.1.0
Any other information:
======================
- The above terminal log are attached.
- The corresponding session directory is also attached
</pre> LTTng-UST - Bug #230 (Resolved): Bus error in applications when using big subbuf size and numberhttps://bugs.lttng.org/issues/2302012-04-26T22:42:13ZRaphaël Beamonteraphael.beamonte@polymtl.ca
<p>When using LTTng UST with big subbuf size (4194304) and number (256), the application is crashing with the following gdb report :</p>
<pre>
Program received signal SIGBUS, Bus error.
[Switching to Thread 0x7ffff61db700 (LWP 17504)]
0x00007ffff79c2acf in channel_create (config=0x7ffff7bd35a0, name=0x7ffff79c91af "relay-discard-mmap", priv_data=0x7ffff61da0b8, priv_data_align=8, priv_data_size=112, priv_data_init=0x7ffff61da3d0,
buf_addr=0x0, subbuf_size=4194304, num_subbuf=256, switch_timer_interval=0, read_timer_interval=200, shm_fd=0x7ffff61da7e0, wait_fd=0x7ffff61da7e8, memory_map_size=0x7ffff61da7f0)
at ring_buffer_frontend.c:492
492 chan->priv_data_offset = shmobj->allocated_len;
</pre>
<p>The lttng-sessiond daemon is giving those information when run with -vvv modes :</p>
<pre>
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:73]
DEBUG1: Dispatching UST registration pid:17500 ppid:17498 uid:1000 gid:1000 sock:19 name:sample (version 2.0) [in thread_dispatch_ust_registration() at main.c:1346]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1334]
DEBUG3: Created hashtable size 4 at 0x1d4b470 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:17500 ppid:17498 uid:1000 gid:1000 sock:19 name:sample (version 2.0) [in ust_app_register() at ust-app.c:1365]
DEBUG2: UST app PID 17500 is compatible with major version 2 (supporting <= 2) [in ust_app_validate_version() at ust-app.c:2625]
DEBUG2: UST app global update for app sock 19 for session id 1 [in ust_app_global_update() at ust-app.c:2295]
DEBUG2: UST app pid: 17500 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:883]
DEBUG3: Created hashtable size 4 at 0x1d4c770 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Shadow copy of session handle -1 [in shadow_copy_session() at ust-app.c:794]
DEBUG2: Channel chanpouet not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:823]
DEBUG3: Created hashtable size 4 at 0x1d521a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x1d52440 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel chanpouet allocated [in alloc_ust_app_channel() at ust-app.c:298]
DEBUG2: UST app shadow copy of channel chanpouet started [in shadow_copy_channel() at ust-app.c:734]
DEBUG2: UST event * not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:761]
DEBUG3: Created hashtable size 4 at 0x1d52a70 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event * allocated [in alloc_ust_app_event() at ust-app.c:333]
DEBUG3: UST app shadow copy of channel chanpouet done [in shadow_copy_channel() at ust-app.c:771]
DEBUG2: UST app session created successfully with handle 2 [in create_ust_app_session() at ust-app.c:907]
Error: Creating channel chanpouet for app (pid: 17500, sock: 19) and session handle 2 with ret -22
DEBUG1: Starting tracing for ust app pid 17500 [in ust_app_start_trace() at ust-app.c:1970]
Error: UST app open metadata failed for app pid:17500 with ret -1
DEBUG3: Opening metadata failed. Cleaning up memory [in create_ust_app_metadata() at ust-app.c:1206]
DEBUG1: PID 17500 unregistering with sock 19 [in ust_app_unregister() at ust-app.c:1395]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1200]
</pre>
<p>The commands used to reproduce the error are the following :</p>
<pre>
$ sudo lttng create pouet
Session pouet created.
Traces will be written in /root/lttng-traces/pouet-20120426-182501
</pre>
<pre>
$ sudo lttng enable-channel chanpouet -u --subbuf-size 4194304 --num-subbuf 256
UST channel chanpouet enabled for session pouet
</pre>
<pre>
$ sudo lttng enable-event * -u -c chanpouet -a
All UST events are enabled in channel chanpouet
</pre>
<pre>
$ sudo lttng start
Tracing started for session pouet
</pre>
<p>The application returning the error in the example found here is the <strong>easy-ust</strong> one, in <strong>doc/examples/</strong>.</p> LTTng-UST - Bug #142 (Resolved): Python application freeze when registering to sessiondhttps://bugs.lttng.org/issues/1422012-03-01T15:30:40ZYannick Brosseauyannick.brosseau@polymtl.ca
<p>A python application freeze when we try to start it.</p>
<p>We get the following error message on the console:<br />libust[11028/11028]: Error: Timed out waiting for ltt-sessiond (in lttng_ust_init() at lttng-ust-comm.c:873)</p>
<p>The corresponding output of lttng-sessiond -vvv:</p>
<p>DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3627]<br />DEBUG1: UST registration received with pid:11028 ppid:11027 uid:0 gid:0 sock:19 name:python (version 2.0) [in thread_registration_apps() at main.c:1392]<br />DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:101]<br />DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1322]<br />DEBUG1: Futex n to 1 wait done [in futex_nto1_wait() at futex.c:88]<br />DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:74]<br />DEBUG1: Dispatching UST registration pid:11028 ppid:11027 uid:0 gid:0 sock:19 name:python (version 2.0) [in thread_dispatch_ust_registration() at main.c:1245]<br />DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1233]<br />DEBUG3: Created hashtable size 4 at 0x21ba4b0 of type 1 [in lttng_ht_new() at hashtable.c:96]<br />DEBUG1: App registered with pid:11028 ppid:11027 uid:0 gid:0 sock:19 name:python (version 2.0) [in ust_app_register() at ust-app.c:1317]<br />DEBUG2: UST app PID 11028 is compatible with major version 2 (supporting <= 2) [in ust_app_validate_version() at ust-app.c:2562]<br />DEBUG2: UST app global update for app sock 19 for session id 1 [in ust_app_global_update() at ust-app.c:2232]<br />DEBUG2: UST app pid: 11028 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:855]<br />DEBUG3: Created hashtable size 4 at 0x21bb7b0 of type 0 [in lttng_ht_new() at hashtable.c:96]<br />DEBUG2: Shadow copy of session handle -1 [in shadow_copy_session() at ust-app.c:766]<br />DEBUG2: Channel channel0 not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:795]<br />DEBUG3: Created hashtable size 4 at 0x21bc5c0 of type 1 [in lttng_ht_new() at hashtable.c:96]<br />DEBUG3: Created hashtable size 4 at 0x21bc860 of type 0 [in lttng_ht_new() at hashtable.c:96]<br />DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:281]<br />DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:706]<br />DEBUG2: UST event * not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:733]<br />DEBUG3: Created hashtable size 4 at 0x21bce90 of type 1 [in lttng_ht_new() at hashtable.c:96]<br />DEBUG3: UST app event * allocated [in alloc_ust_app_event() at ust-app.c:316]<br />DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:743]</p> LTTng-UST - Bug #10 (Resolved): tor instrumentation only works partlyhttps://bugs.lttng.org/issues/102012-02-10T01:25:58ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>When instrumenting tor, only some of the tracepoints are fired, event though all events are enabled.</p>
<p>(skipping bug reproduction details, since the bug is already solved)</p>
<p>Solved by commit:</p>
<p>commit 51920067af7b1049413c1b8c30ee254afbd4e448<br />Author: Mathieu Desnoyers <<a class="email" href="mailto:mathieu.desnoyers@efficios.com">mathieu.desnoyers@efficios.com</a>><br />Date: Thu Feb 9 18:55:44 2012 -0500</p>
<pre><code>Fix tracepoint.h multiple .o within module/core exec linkage bug</code></pre>
<pre><code>We need all symbols looked up with dlopen to share the same linkage<br /> property as the __tracepoint_registered variable (shared across .o in a<br /> module/executable), otherwise only the first .o which runs its<br /> constructor will have those defined.</code></pre>
<pre><code>Caused some tracepoints not to be traced in non-_LGPL_SOURCE<br /> applications, due to the check:</code></pre>
<pre><code>if (!TP_RCU_LINK_TEST()) \<br /> return;</code></pre>
<pre><code>Signed-off-by: Mathieu Desnoyers &lt;<a class="email" href="mailto:mathieu.desnoyers@efficios.com">mathieu.desnoyers@efficios.com</a>&gt;</code></pre>