LTTng bugs repository: Issueshttps://bugs.lttng.org/https://bugs.lttng.org/themes/lttng/favicon/a.ico?14249722912024-02-21T17:04:43ZLTTng bugs repository
Redmine Babeltrace - Feature #1410 (New): Add pretty-print sink options to override how to format floatin...https://bugs.lttng.org/issues/14102024-02-21T17:04:43ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>Babeltrace 2, just like its predecessor babeltrace 1.5, uses "%g" to print floating point numbers.</p>
<p>It would be useful to let users optionally override the formatting for floating point numbers, perhaps with a pretty print sink option. They could then choose if exponent notation should be used or not, choose the precision, etc.</p> Babeltrace - Bug #1388 (New): Assertion `this->active_stream_iter == 0` failedhttps://bugs.lttng.org/issues/13882023-09-08T18:57:03ZSimon Marchisimon.marchi@polymtl.ca
<p>Steps:</p>
<ol>
<li><code>lttng create my-session --live</code></li>
<li><code>lttng enable-event -u -a</code></li>
<li><code>lttng start</code></li>
<li><code>./src/cli/babeltrace2 'net://127.0.0.1/host/smarchi-efficios/my-session'</code></li>
<li>Run the hello app from the lttng-ust tests: <code>lttng-ust/tests/hello/hello</code></li>
<li>While events print on the babeltrace terminal, type ctrl-C</li>
</ol>
<p>I get:</p>
<p><code> (╯°□°)╯︵ ┻━┻ /home/smarchi/src/babeltrace/src/plugins/ctf/lttng-live/lttng-live.cpp:214: ~lttng_live_msg_iter(): Assertion `this->active_stream_iter == 0` failed.</code></p> Babeltrace - Bug #1384 (New): Assertion `bt_value_get_type(map) == BT_VALUE_TYPE_MAP` failshttps://bugs.lttng.org/issues/13842023-08-08T18:07:42ZErica Bugden
<p>Hello! I triggered an internal assertion while trying to, presumably incorrectly, query the lttng-live component class.</p>
<a name="Software"></a>
<h1 >Software<a href="#Software" class="wiki-anchor">¶</a></h1>
<ul>
<li>lttng tools: <code>lttng (LTTng Trace Control) 2.14.0-pre - O-Beer - v2.12.0-rc1-1528-g5983bb6d3</code></li>
<li>babeltrace2: <code>Babeltrace 2.1.0-rc1 "Codename TBD" [v1.2.0-3704-gdbea6be2]</code> (configured with plugins, python bindings support)</li>
</ul>
<a name="Procedure"></a>
<h1 >Procedure<a href="#Procedure" class="wiki-anchor">¶</a></h1>
<ul>
<li>Start root session daemon: <code>$sudo lttng-sessiond --daemonize</code></li>
<li>Create live session: <code>$lttng create my-session --live</code></li>
<li>Enable events: <code>$lttng enable-event --kernel sched-switch,sched_process_fork</code></li>
<li>Start tracing <code>$lttng start</code></li>
<li>Run python script: <code>python3 lttng-live.py</code> (see below)
<ul>
<li>Assertion</li>
</ul></li>
</ul>
<a name="Python-script"></a>
<h1 >Python script<a href="#Python-script" class="wiki-anchor">¶</a></h1>
<p>Note: The script is noisy as some code/comments are irrelevant/incorrect/inconsistent. (It's originally based on the query example in the Python bindings documentation.)</p>
<pre>
import bt2
import sys
# Get the `source.ctf.fs` component class from the `ctf` plugin.
# `source.ctf.lttng-live` component class instead
# (list plugins/components with $babeltrace2 list-plugins)
comp_cls = bt2.find_plugin('ctf').source_component_classes['lttng-live']
# The `babeltrace.support-info` query operation expects a `type`
# parameter (set to `directory` here) and an `input` parameter (the
# actual path or string to check, in this case the first command-line
# argument).
#
# See `babeltrace2-query-babeltrace.support-info(7)`.
params = {
'url': 'net://localhost/host/luna/my-session'
}
'''
params = {
'type': 'string',
'input': sys.argv[1],
}
'''
# Create a query executor.
#
# This is the environment in which query operations happens. The
# queried component class has access to this executor, for example to
# retrieve the query operation's logging level.
query_exec = bt2.QueryExecutor(comp_cls, 'sessions',
'inputs=net://localhost/host/luna/my-session')
'''
query_exec = bt2.QueryExecutor(comp_cls, 'babeltrace.support-info',
params)
'''
# Query the component class through the query executor.
#
# This method returns the result.
result = query_exec.query()
# Print the result.
print(result)
# Try to iterate on the trace.
'''
for msg in bt2.TraceCollectionMessageIterator('net://localhost/host/luna/my-session'):
if type(msg) is bt2._EventMessageConst:
print(msg.event.name)
'''
</pre>
<p>If I remember correctly, <strong>the script line change that triggered the assertion was expressing the query parameters directly as a string</strong> (rather than a dictionary). As in this:</p>
<pre>
query_exec = bt2.QueryExecutor(comp_cls, 'sessions',
'inputs=net://localhost/host/luna/my-session')
</pre>
<p>instead of this:</p>
<pre>
params = {
'url': 'net://localhost/host/luna/my-session'
}
query_exec = bt2.QueryExecutor(comp_cls, 'sessions',
params)
</pre>
<a name="Output"></a>
<h1 >Output<a href="#Output" class="wiki-anchor">¶</a></h1>
<pre>
erica@luna:~$ python3 lttng-live.py
(╯°□°)╯︵ ┻━┻ param-validation.c:196: validate_map_value(): Assertion `bt_value_get_type(map) == BT_VALUE_TYPE_MAP` failed.
Aborted (core dumped)
</pre> Babeltrace - Bug #1374 (New): Babeltrace fails to read trace with no data stream type ID when the...https://bugs.lttng.org/issues/13742023-04-26T17:57:32ZErica Bugden
<p>Babeltrace is not able to read a trace that does not contain data stream IDs (empty packet header) when the metadata specifies an ID for the stream. Trace Compass is also unable to read this trace. If the lines mentioning the stream ID are removed from the metadata, then babeltrace is able to read the trace.</p>
<a name="Does-this-need-to-be-fixed"></a>
<h3 >Does this need to be fixed?<a href="#Does-this-need-to-be-fixed" class="wiki-anchor">¶</a></h3>
<p>This was first reported as a barectf issue <a class="external" href="https://github.com/efficios/barectf/issues/28">https://github.com/efficios/barectf/issues/28</a> , but after further consideration the issue appears to be in a grey area in the CTF 1.8 specification. Whether it is the CTF generator's (barectf) responsibility or the CTF reader's responsibility is up for debate.</p>
<p>The superfluous metadata information need not prevent the trace from being parsed. For example, yactfr <a class="external" href="https://github.com/eepp/yactfr">https://github.com/eepp/yactfr</a> is able to read the trace. However, considering that:</p>
<ul>
<li>At least two CTF readers (babeltrace and Trace Compass) cannot read the trace, and</li>
<li>It is easy to fix in barectf (Proposed fix: <a class="external" href="https://review.lttng.org/c/barectf/+/9868">https://review.lttng.org/c/barectf/+/9868</a> )</li>
</ul>
<p>this is not a high priority issue in babeltrace.</p>
<a name="Context"></a>
<h1 >Context<a href="#Context" class="wiki-anchor">¶</a></h1>
<p>- Background and reproducer: barectf github issue <a class="external" href="https://github.com/efficios/barectf/issues/28">https://github.com/efficios/barectf/issues/28</a> <br />- Background and specification discussion: barectf fix <a class="external" href="https://review.lttng.org/c/barectf/+/9868">https://review.lttng.org/c/barectf/+/9868</a></p> Babeltrace - Bug #1348 (New): Assertion failure when passing `smalltrace` CTF test trace twice to...https://bugs.lttng.org/issues/13482022-03-11T21:29:01ZFrancis Deslauriersfrancis.deslauriers@efficios.com
<p>Command used:<br /><pre>
src/cli/babeltrace2 tests/data/ctf-traces/succeed/smalltrace tests/data/ctf-traces/succeed/smalltrace
</pre></p>
<p>The same issue can be reproduce with the <code>env-warning</code> test trace.</p>
<p>Error print out:<br /><pre>
03-11 16:21:26.766 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:64 Babeltrace 2 library precondition not satisfied.
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:66 ------------------------------------------------------------------------
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:67 Condition ID: `pre:self-component-source-add-output-port:output-port-is-unique`.
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:69 Function: bt_self_component_source_add_output_port().
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:70 ------------------------------------------------------------------------
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:71 Error is:
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:73 Output port name is not unique: name="2a6422d0-6cee-11e0-8c08-cb07d7b3a564 | 0 | /home/frdeso/projets/babeltrace/tests/data/ctf-traces/succeed/smalltrace/dummystream", comp-addr=0x5555555961c0, comp-name="auto-disc-source-ctf-fs", comp-log-level=WARNING, comp-class-type=SOURCE, comp-class-name="fs", comp-class-partial-descr="Read CTF traces from the file sy"
03-11 16:21:26.767 2579249 2579249 F LIB/ASSERT-COND bt_lib_assert_cond_failed@assert-cond.c:76 Aborting...
Program received signal SIGABRT, Aborted.
</pre></p>
<p>GDB stack trace:<br /><pre>
#0 0x00007ffff7bd003b in raise () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff7baf859 in abort () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007ffff7ee32e5 in bt_common_abort () at common.c:2111
#3 0x00007ffff7ee408a in bt_lib_assert_cond_failed (cond_type=cond_type@entry=0x7ffff7f521c4 "pre", func=func@entry=0x7ffff7f59fc0 <__func__.17520> "bt_self_component_source_add_output_port", id_suffix=id_suffix@entry=0x7ffff7f59e51 "output-port-is-unique", fmt=fmt@entry=0x7ffff7f59ec8 "Output port name is not unique: name=\"%s\", %![comp-]c") at assert-cond.c:77
#4 0x00007ffff7f00410 in bt_self_component_source_add_output_port (self_comp=0x5555555961c0, name=0x5555555d01f0 "2a6422d0-6cee-11e0-8c08-cb07d7b3a564 | 0 | /home/frdeso/projets/babeltrace/tests/data/ctf-traces/succeed/smalltrace/dummystream", user_data=0x5555555d8440, self_port=0x0) at component-source.c:127
#5 0x00007ffff7ab7622 in create_one_port_for_trace (ctf_fs=0x555555596360, ctf_fs_trace=0x555555594d40, ds_file_group=0x5555555cb8c0, self_comp_src=0x5555555961c0) at fs.cpp:436
#6 0x00007ffff7ab735f in create_ports_for_trace (ctf_fs=0x555555596360, ctf_fs_trace=0x555555594d40, self_comp_src=0x5555555961c0) at fs.cpp:469
#7 0x00007ffff7ab2fc8 in ctf_fs_create (params=0x5555555bc2e0, self_comp_src=0x5555555961c0) at fs.cpp:2287
#8 0x00007ffff7ab2ebc in ctf_fs_init (self_comp_src=0x5555555961c0, config=0x0, params=0x5555555bc2e0, init_method_data=0x0) at fs.cpp:2311
#9 0x00007ffff7f05bb3 in add_component_with_init_method_data (graph=graph@entry=0x5555555bd240, comp_cls=comp_cls@entry=0x5555555b80e0, init_method=0x7ffff7ab2e90 <ctf_fs_init(bt_self_component_source*, bt_self_component_source_configuration*, bt_value const*, void*)>, name=name@entry=0x5555555bc2b0 "auto-disc-source-ctf-fs", params=params@entry=0x5555555bc2e0, init_method_data=init_method_data@entry=0x0, log_level=BT_LOGGING_LEVEL_WARNING, user_component=0x7fffffffe0a0, api_func=0x7ffff7f5c400 <__func__.18097> "bt_graph_add_source_component", init_method_name=0x7ffff7f5ca48 "bt_component_class_source_initialize_method") at graph.c:1048
#10 0x00007ffff7f0654f in add_source_component_with_initialize_method_data (graph=0x5555555bd240, comp_cls=0x5555555b80e0, name=0x5555555bc2b0 "auto-disc-source-ctf-fs", params=0x5555555bc2e0, init_method_data=0x0, log_level=BT_LOGGING_LEVEL_WARNING, component=0x7fffffffe0a0, api_func=0x7ffff7f5c400 <__func__.18097> "bt_graph_add_source_component") at graph.c:1127
#11 0x00007ffff7f0932d in bt_graph_add_source_component (graph=<optimized out>, comp_cls=comp_cls@entry=0x5555555b80e0, name=<optimized out>, params=<optimized out>, log_level=<optimized out>, component=component@entry=0x7fffffffe0a0) at graph.c:1152
#12 0x0000555555561c42 in cmd_run_ctx_create_components_from_config_components (ctx=ctx@entry=0x7fffffffe170, cfg_components=<optimized out>, cfg_components=<optimized out>) at babeltrace2.c:2259
#13 0x000055555555cda9 in cmd_run_ctx_create_components (ctx=0x7fffffffe170) at babeltrace2.c:2355
#14 cmd_run (cfg=0x55555559fc70) at babeltrace2.c:2469
#15 main (argc=<optimized out>, argv=<optimized out>) at babeltrace2.c:2679
</pre></p>
<p>Commit:<br /><pre>
commit 53a47a3f01d6bfa4e940e1943e7645cb89d04cd5 (HEAD -> master, review/master, origin/master, origin/HEAD, eepp,simark/master)
Author: Michael Jeanson <mjeanson@efficios.com>
Date: Wed Mar 2 13:25:05 2022 -0500
fix: add dependency between cli bin and plugins when built-in
</pre></p> Babeltrace - Bug #1322 (New): Assert in ctf_msg_iter_destroy()https://bugs.lttng.org/issues/13222021-08-15T23:30:51ZSergei Dyshel
<p>#0 0x00007ff0426ad495 in raise () from /lib64/libc.so.6<br />#1 0x00007ff0426aec75 in abort () from /lib64/libc.so.6<br />#2 0x00007ff0426eb3a7 in __libc_message () from /lib64/libc.so.6<br />#3 0x00007ff0426f0dee in malloc_printerr () from /lib64/libc.so.6<br />#4 0x00007ff0426f3c3d in _int_free () from /lib64/libc.so.6<br />#5 0x00007ff041fd91cd in ctf_msg_iter_destroy (msg_it=0x47d700) at msg-iter.c:2870<br />#6 0x00007ff041ffa61d in lttng_live_stream_iterator_destroy (stream_iter=0x57e520)<br /> at data-stream.c:300<br /><a class="issue tracker-1 status-5 priority-5 priority-high2 closed" title="Bug: Double PID registering and unregistering race (Resolved)" href="https://bugs.lttng.org/issues/7">#7</a> 0x00007ff042c858c4 in g_ptr_array_foreach (array=0x446140,<br /> func=0x7ff041ffa5f0 <lttng_live_stream_iterator_destroy>, user_data=0x0) at garray.c:1500<br />#8 0x00007ff042c859ed in ptr_array_free (flags=<optimized out>, array=0x446140)<br /> at garray.c:1086<br /><a class="issue tracker-1 status-5 priority-3 priority-lowest closed" title="Bug: LTTng-UST java jni wrapper does not build with OpenJDK (Resolved)" href="https://bugs.lttng.org/issues/9">#9</a> g_ptr_array_free (array=0x446140, free_segment=free_segment@entry=1) at garray.c:1073<br /><a class="issue tracker-1 status-5 priority-6 priority-highest closed" title="Bug: tor instrumentation only works partly (Resolved)" href="https://bugs.lttng.org/issues/10">#10</a> 0x00007ff041ff625b in lttng_live_destroy_trace (trace=0x4a6260) at lttng-live.c:164<br /><a class="issue tracker-1 status-5 priority-4 priority-default closed" title="Bug: Python sometimes registers to sessiond as lttng-ust application (Resolved)" href="https://bugs.lttng.org/issues/11">#11</a> 0x00007ff042c858c4 in g_ptr_array_foreach (array=0x4463a0,<br /> func=0x7ff041ff61f0 <lttng_live_destroy_trace>, user_data=0x0) at garray.c:1500<br />#12 0x00007ff042c859ed in ptr_array_free (flags=<optimized out>, array=0x4463a0)<br /> at garray.c:1086<br />#13 g_ptr_array_free (array=0x4463a0, free_segment=free_segment@entry=1) at garray.c:1073<br />#14 0x00007ff041ff6356 in lttng_live_destroy_session (session=0x44a4a0) at lttng-live.c:300<br /><a class="issue tracker-2 status-7 priority-3 priority-lowest overdue behind-schedule" title="Feature: LTTng simple trace (Confirmed)" href="https://bugs.lttng.org/issues/15">#15</a> 0x00007ff042c858c4 in g_ptr_array_foreach (array=0x4462e0,<br /> func=0x7ff041ff62c0 <lttng_live_destroy_session>, user_data=0x0) at garray.c:1500<br />#16 0x00007ff042c859ed in ptr_array_free (flags=<optimized out>, array=0x4462e0)<br /> at garray.c:1086<br />#17 g_ptr_array_free (array=0x4462e0, free_segment=free_segment@entry=1) at garray.c:1073<br /><a class="issue tracker-2 status-5 priority-4 priority-default closed" title="Feature: Define the libbabeltrace API for trace reading (Resolved)" href="https://bugs.lttng.org/issues/18">#18</a> 0x00007ff041ff6806 in lttng_live_msg_iter_destroy (lttng_live_msg_iter=0x4a5a00)<br /> at lttng-live.c:323<br /><a class="issue tracker-2 status-5 priority-4 priority-default closed" title="Feature: Make use tracer "environment" metadata (Resolved)" href="https://bugs.lttng.org/issues/19">#19</a> lttng_live_msg_iter_finalize (self_msg_iter=<optimized out>) at lttng-live.c:351<br /><a class="issue tracker-2 status-5 priority-3 priority-lowest closed" title="Feature: Finish x86 syscalls (Resolved)" href="https://bugs.lttng.org/issues/20">#20</a> 0x00007ff042de2417 in bt_message_iterator_try_finalize (iterator=iterator@entry=0x4a5890)<br /> at iterator.c:219<br /><a class="issue tracker-2 status-5 priority-4 priority-default closed" title="Feature: Emit tracer environment metadata for the kernel (Resolved)" href="https://bugs.lttng.org/issues/21">#21</a> 0x00007ff042ddc310 in bt_connection_end (conn=conn@entry=0x4a54b0,<br /> try_remove_from_graph=try_remove_from_graph@entry=false) at connection.c:213<br /><a class="issue tracker-2 status-5 priority-4 priority-default closed" title="Feature: Show "syscalls activated" in output (Resolved)" href="https://bugs.lttng.org/issues/22">#22</a> 0x00007ff042ddc62e in destroy_connection (obj=0x4a54b0) at connection.c:65<br /><a class="issue tracker-2 status-8 priority-4 priority-default closed" title="Feature: Implement trace log levels (Invalid)" href="https://bugs.lttng.org/issues/23">#23</a> 0x00007ff042c858c4 in g_ptr_array_foreach (array=0x43a0e0, func=0x7ff042ddc880 <bt_object_try_spec_release>, user_data=0x0) at garray.c:1500<br /><a class="issue tracker-2 status-5 priority-4 priority-default closed" title="Feature: Add a helper script to automatically generate the probe header file (Resolved)" href="https://bugs.lttng.org/issues/24">#24</a> 0x00007ff042c859ed in ptr_array_free (flags=<optimized out>, array=0x43a0e0) at garray.c:1086<br /><a class="issue tracker-2 status-5 priority-4 priority-default closed" title="Feature: Emit tracer environment metadata (Resolved)" href="https://bugs.lttng.org/issues/25">#25</a> g_ptr_array_free (array=0x43a0e0, free_segment=free_segment@entry=1) at garray.c:1073<br /><a class="issue tracker-2 status-5 priority-3 priority-lowest closed" title="Feature: Add a "lttng view" command (Resolved)" href="https://bugs.lttng.org/issues/26">#26</a> 0x00007ff042ddc934 in destroy_graph (obj=0x43c000) at graph.c:114<br />#27 0x000000000040add3 in cmd_run_ctx_destroy (ctx=ctx@entry=0x7ffe56fd41c0) at babeltrace2.c:1703<br /><a class="issue tracker-2 status-5 priority-3 priority-lowest closed" title="Feature: Implement the State Dump (Resolved)" href="https://bugs.lttng.org/issues/28">#28</a> 0x0000000000408236 in cmd_run (cfg=0x4438e0) at babeltrace2.c:2556<br /><a class="issue tracker-2 status-5 priority-3 priority-lowest closed" title="Feature: Add integration with SystemTap/DTrace probes with sdt.h (Resolved)" href="https://bugs.lttng.org/issues/29">#29</a> main (argc=<optimized out>, argv=<optimized out>) at babeltrace2.c:2691</p>
<p>Details of lttng/babeltrace session as in <a class="external" href="https://bugs.lttng.org/issues/1319">https://bugs.lttng.org/issues/1319</a></p> Babeltrace - Bug #1319 (New): Assert in emit_inactivity_messagehttps://bugs.lttng.org/issues/13192021-06-17T11:54:52ZSergei Dyshel
<p>While using babeltrace 2.0.3 with lttng-live (latest lttng version) we encountered the following assert:</p>
<pre>
(gdb) bt
#0 0x00007f9023fc3495 in raise () from /lib64/libc.so.6
#1 0x00007f9023fc4c75 in abort () from /lib64/libc.so.6
#2 0x00007f902391d8d3 in bt_common_abort () at common.c:2111
#3 0x00007f902391b9ff in bt_common_assert_failed (file=0x7f9023921495 "lttng-live.c", line=613, func=0x7f902393f500 <__func__.17246> "emit_inactivity_message", assertion=0x7f9023931c70 "stream_iter->trace->clock_class")
at assert.c:40
#4 0x00007f902390be67 in emit_inactivity_message (stream_iter=0x472100, timestamp=<optimized out>, message=0x7ffe76aa8d98, lttng_live_msg_iter=0x471810) at lttng-live.c:613
#5 lttng_live_iterator_next_handle_one_quiescent_stream (message=0x7ffe76aa8d98, lttng_live_stream=0x472100, lttng_live_msg_iter=0x471810) at lttng-live.c:653
#6 lttng_live_iterator_next_msg_on_stream (curr_msg=0x7ffe76aa8d98, stream_iter=0x472100, lttng_live_msg_iter=0x471810) at lttng-live.c:961
#7 next_stream_iterator_for_trace (live_trace=0x4721a0, live_trace=0x4721a0, youngest_trace_stream_iter=<synthetic pointer>, lttng_live_msg_iter=0x471810) at lttng-live.c:1093
#8 next_stream_iterator_for_session (youngest_session_stream_iter=<synthetic pointer>, session=0x471d70, lttng_live_msg_iter=0x471810) at lttng-live.c:1325
#9 lttng_live_msg_iter_next (self_msg_it=<optimized out>, msgs=0x471780, capacity=15, count=0x7ffe76aa8ee8) at lttng-live.c:1518
#10 0x00007f90247031e2 in call_iterator_next_method (capacity=15, user_count=0x7ffe76aa8ee8, msgs=0x471780, iterator=0x4716a0) at iterator.c:803
#11 bt_message_iterator_next (iterator=0x4716a0, msgs=msgs@entry=0x7ffe76aa8ee0, user_count=user_count@entry=0x7ffe76aa8ee8) at iterator.c:859
#12 0x00007f90238841e9 in muxer_upstream_msg_iter_next (is_ended=<synthetic pointer>, muxer_upstream_msg_iter=0x471fc0) at muxer.c:399
#13 validate_muxer_upstream_msg_iter (is_ended=<synthetic pointer>, muxer_upstream_msg_iter=0x471fc0) at muxer.c:958
#14 validate_muxer_upstream_msg_iters (muxer_msg_iter=0x471650) at muxer.c:985
#15 muxer_msg_iter_do_next_one (msg=0x449850, muxer_msg_iter=0x471650, muxer_comp=0x4524f0) at muxer.c:1048
#16 muxer_msg_iter_do_next (count=0x7ffe76aa8f70, capacity=15, msgs=0x449850, muxer_msg_iter=0x471650, muxer_comp=0x4524f0) at muxer.c:1132
#17 muxer_msg_iter_next (self_msg_iter=0x471570, msgs=0x449850, capacity=15, count=0x7ffe76aa8f70) at muxer.c:1414
#18 0x00007f90247031e2 in call_iterator_next_method (capacity=15, user_count=0x7ffe76aa8f70, msgs=0x449850, iterator=0x471570) at iterator.c:803
#19 bt_message_iterator_next (iterator=0x471570, msgs=msgs@entry=0x7ffe76aa8f78, user_count=user_count@entry=0x7ffe76aa8f70) at iterator.c:859
#20 0x00007f9023821514 in bx_view_consume (comp=0x43a7d0) at traces//babeltrace-plugin/component.cc:272
#21 0x00007f90246ff3d8 in consume_graph_sink (comp=0x43a7d0) at graph.c:447
#22 consume_sink_node (graph=0x43b7d0, node=0x442e00) at graph.c:491
#23 consume_no_check (api_func=<synthetic pointer>, graph=0x43b7d0) at graph.c:566
#24 bt_graph_run (graph=0x43b7d0) at graph.c:710
#25 0x0000000000408a81 in cmd_run (cfg=0x451eb0) at babeltrace2.c:2485
#26 main (argc=<optimized out>, argv=<optimized out>) at babeltrace2.c:2673
</pre>
<p>I did initial prints in gdb to see that this is not some kind of obvious memory corruption:<br /><pre>
(gdb) p stream_iter->trace
$1 = (struct lttng_live_trace *) 0x4721a0
(gdb) p stream_iter->trace->clock_class
$2 = (const bt_clock_class *) 0x0
(gdb) p stream_iter->trace[0]
$3 = {log_level = BT_LOGGING_LEVEL_WARNING, self_comp = 0x43c050, session = 0x471d70, id = 1, trace = 0x66fc30,
trace_class = 0x66bef0, metadata = 0x66bb00, clock_class = 0x0, stream_iterators = 0x442d20,
metadata_stream_state = LTTNG_LIVE_METADATA_STREAM_STATE_NOT_NEEDED}
(gdb) p stream_iter->trace->trace_class
$4 = (bt_trace_class *) 0x66bef0
(gdb) p stream_iter->trace->trace_class->stream_classes
$5 = (GPtrArray *) 0x43a4a0
(gdb) p stream_iter->trace->trace_class->stream_classes->len
$6 = 0
</pre></p>
<p>Unfortunately I can't attach the coredump here but I can provide any relevant information from it.</p> Babeltrace - Feature #1300 (New): babeltrace2 lacks knowledge of bitwise enum produced by lttng-m...https://bugs.lttng.org/issues/13002021-03-23T17:41:47ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>This is a follow up on <a class="external" href="https://review.lttng.org/c/babeltrace/+/3045">https://review.lttng.org/c/babeltrace/+/3045</a> now that end users are starting to contact us wondering why up-to-date lttng and babeltrace2 show incomplete information for bitwise enums.</p>
<p>I think we should implement a better stop-gap solution while awaiting CTF2. I recommend that we specialize the babeltrace2 CTF input plugin to detect traces produced by the lttng-modules kernel tracer, for specific known (hardcoded) events and fields which have a bitwise enum semantic, and use this hardcoded knowledge to print the correct bitwise enum to the end user rather than "<unknown>".</p>
<p>This should ensure the current producer/consumer tools work well together (show complete information about those bitwise enums) without requiring to modify tons of documentation about the specific flags needed for bt2 to handle lttng traces appropriately. And this would not lead to misleading scenarios where we print an unknown value as a bitwise enum by mistake.</p>
<p>Hardcoded producer detection/event/fields is of course a last resort solution awaiting proper self-description in the upcoming CTF2 spec.</p> Babeltrace - Bug #1260 (New): Babeltrace 2 refuses a trace when a previous packet has an end time...https://bugs.lttng.org/issues/12602020-04-28T18:29:52ZGeneviève Bastiengbastien+lttng@versatic.net
<p>With babeltrace 1, the trace is read fine, event timestamps are monotonic. With babeltrace2 it aborts with message</p>
<p>04-22 16:58:59.461 97893 97893 E PLUGIN/FLT.UTILS.MUXER <a class="email" href="mailto:muxer_msg_iter_do_next_one@muxer.c">muxer_msg_iter_do_next_one@muxer.c</a>:1079 [muxer] Youngest upstream message iterator wrapper's timestamp is less than muxer's message iterator's last returned timestamp: muxer-msg-iter-addr=0x55b2214faf20, ts=1575594527642470600, last-returned-ts=1575594527642472275</p>
<p>Some investigation shows that the reason for this is that end time of a packet > start time of next packet in a stream (pktB.begin < pktA.end)</p>
<p>However, from the spec, it would seem that this case should be supported:</p>
<pre><code>Time-stamp at the beginning and timestamp at the end of the event packet. Both timestamps are written in the packet header, but sampled respectively while (or before) writing the first event and while (or after) writing the last event in the packet. The inclusive range between these timestamps should include all event timestamps assigned to events contained within the packet. The timestamp at the beginning of an event packet is guaranteed to be below or equal the timestamp at the end of that event packet. The timestamp at the end of an event packet is guaranteed to be below or equal the timestamps at the end of any following packet within the same stream. See Clocks for more detail.</code></pre>
<p>I made bt2 output some debug about the message types it gets when the error occurs and here is the output:</p>
<p>4-22 21:41:02.616 203722 203722 F LIB/MSG-ITER <a class="email" href="mailto:clock_snapshots_are_monotonic_one@iterator.c">clock_snapshots_are_monotonic_one@iterator.c</a>:580 Got a message with timestamp 1575594328184404010 of type 4<br />04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER <a class="email" href="mailto:clock_snapshots_are_monotonic_one@iterator.c">clock_snapshots_are_monotonic_one@iterator.c</a>:580 Got a message with timestamp 1575594471692837471 of type 4<br />04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER <a class="email" href="mailto:clock_snapshots_are_monotonic_one@iterator.c">clock_snapshots_are_monotonic_one@iterator.c</a>:580 Got a message with timestamp 1575594527642472275 of type 16 <-- notice the packet ends much later than the last event in it<br />04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER <a class="email" href="mailto:clock_snapshots_are_monotonic_one@iterator.c">clock_snapshots_are_monotonic_one@iterator.c</a>:580 Got a message with timestamp 1575594527642470600 of type 8 <--<br />04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER <a class="email" href="mailto:call_iterator_next_method@iterator.c">call_iterator_next_method@iterator.c</a>:802 Babeltrace 2 library postcondition not satisfied; error is:<br />04-22 21:41:02.616 203722 203722 F LIB/MSG-ITER <a class="email" href="mailto:call_iterator_next_method@iterator.c">call_iterator_next_method@iterator.c</a>:802 Clock snapshots are not monotonic</p>
<p>type 16 is packet end and type 8 is packet begin. The non-monotonicity does not involve events, only packet times.</p> Babeltrace - Bug #1228 (New): calling seek to beginning after seek to ns from originhttps://bugs.lttng.org/issues/12282020-02-17T21:14:40ZSimon Marchisimon.marchi@polymtl.ca
<p>I haven't tried, but from my understanding of the message iterator, this sequence should trigger a bug:</p>
<p>1. seek an iterator to some ns_from_origin. It uses auto seek, therefore buffers some messages in the auto seek queue and replaces the <code>next</code> method with <code>post_auto_seek_next</code>.<br />2. seek an iterator to the beginning.<br />3. Consume some messages</p>
<p>Even though we have seeked to beginning, the <code>post_auto_seek_next</code> callback is still installed, and will returned the messages from 1. The caller would expect the messages from the beginning to be returned.</p>
<p>There might be other cases like this were the auto seek state should be trashed but isn't.</p> Babeltrace - Feature #1226 (New): Allow making graph execution more "event-based"https://bugs.lttng.org/issues/12262020-02-17T21:10:09ZSimon Marchisimon.marchi@polymtl.ca
<p>Currently, when using the lttng-live source component class, the source component will return TRY_AGAIN if it has no messages to return but the connection is still open. The graph will return TRY_AGAIN to the user, which can then run the graph again to retry. The source component might have some data available, or it might also return TRY_AGAIN again. This effectively constitutes a busy loop, consuming CPU to check if new data is available.</p>
<p>It would be better to have the process block on a syscall if there's nothing to consume, and be woken up when some data arrives. Here's how I would see it:</p>
<p>1. A source that may return TRY_AGAIN would register a file descriptor to be used as an asynchronous event source, along with a callback<br />2. When a sink's consume method returns TRY_AGAIN, that sink is placed in the "inactive sinks" list<br />3. If there are no active sinks, bt_graph_run (or some new function) would <code>poll</code> all event sources, waiting for one to become readable.<br />4. It would call the callback associated to the event source(s) that became readable<br />5. The source component would send some kind of signal downstream that would trickle down to the sinks that previously became inactive, those sinks would inform the graph, who would put them back in the "active" list</p>
<p>Of course, many problems come to mind, such as how to deal with portability, multiple sinks where one keeps producing and one that becomes inactive and active again (how do you make sure not to starve the one that became inactive), how to evolve the API to include that without breaking any existing behavior, etc.</p> Babeltrace - Bug #1221 (New): Babeltrace 2 sometimes fail on live trace with lttng-clear featurehttps://bugs.lttng.org/issues/12212020-02-17T20:52:19ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>Babeltrace 2 sometimes fail on live trace with lttng-clear feature</p>
<p>This may happen in a scenario where per-pid buffers are used, an application has just quit, and babeltrace 2 observes a stream in make_viewer_streams, but then fails to open the associated index or data file on the first get_next_index because it has been unlinked by clear.</p>
<p>The babeltrace output is:</p>
<pre>
12-04 14:01:48.455 11884 11884 E PLUGIN/CTF/MSG-ITER create_msg_stream_end@msg-iter.c:2464 [lttng-live] Cannot create stream for stream message: notit-addr=0x55b89f957980
12-04 14:01:48.455 11884 11884 W LIB/MSG-ITER bt_self_component_port_input_message_iterator_next@iterator.c:906 Component input port message iterator's "next" method failed: iter-addr=0x55b89f93f510, iter-upstream-comp-name="lttng-live", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
12-04 14:01:48.455 11884 11884 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:444 [muxer] Error or unsupported status code: status-code=-1
12-04 14:01:48.455 11884 11884 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:975 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x55b89f950950, muxer-upstream-msg-iter-wrap-addr=0x55b89f9415d0
12-04 14:01:48.455 11884 11884 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1371 [muxer] Cannot get next message: comp-addr=0x55b89f93ebc0, muxer-comp-addr=0x55b89f93ec40, muxer-msg-iter-addr=0x55b89f950950, msg-iter-addr=0x55b89f93f3a0, status=ERROR
12-04 14:01:48.455 11884 11884 W LIB/MSG-ITER bt_self_component_port_input_message_iterator_next@iterator.c:906 Component input port message iterator's "next" method failed: iter-addr=0x55b89f93f3a0, iter-upstream-comp-name="muxer", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
12-04 14:01:48.455 11884 11884 W LIB/GRAPH consume_graph_sink@graph.c:596 Component's "consume" method failed: status=ERROR, comp-addr=0x55b89f93ed30, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x55b89f94c740, comp-class-so-handle-path="/usr/local/lib/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
12-04 14:01:48.456 11884 11884 E CLI cmd_run@babeltrace2.c:2574 Graph failed to complete successfully
ERROR: [Babeltrace CLI] (babeltrace2.c:2574)
Graph failed to complete successfully
CAUSED BY [Babeltrace library] (graph.c:596)
Component's "consume" method failed: status=ERROR, comp-addr=0x55b89f93ed30,
comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK,
comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages
(`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x55b89f94c740,
comp-class-so-handle-path="/usr/local/lib/babeltrace2/plugins/babeltrace-plugin-text.so",
comp-input-port-count=1, comp-output-port-count=0
CAUSED BY [Babeltrace library] (iterator.c:906)
Component input port message iterator's "next" method failed:
iter-addr=0x55b89f93f3a0, iter-upstream-comp-name="muxer",
iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER,
iter-upstream-comp-class-name="muxer",
iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu",
iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
CAUSED BY [Babeltrace library] (iterator.c:906)
Component input port message iterator's "next" method failed:
iter-addr=0x55b89f93f510, iter-upstream-comp-name="lttng-live",
iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE,
iter-upstream-comp-class-name="lttng-live",
iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon",
iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
</pre>
<p>notit->stream is expected not to be NULL when reaching the state STATE_EMIT_MSG_STREAM_END, but if no packet was received, it is indeed still NULL, because it is the packet header being read that moves to the STATE_CHECK_EMIT_MSG_STREAM_BEGINNING state (after_packet_context_state()).</p> Babeltrace - Bug #1144 (New): Babeltrace 1.5.3 intermittent error on lttng-live hookinghttps://bugs.lttng.org/issues/11442017-12-15T19:45:21ZJonathan Rajotte Julienjonathan.rajotte-julien@efficios.com
<pre>
[error] get_next_index failed
[error] Stream 18446744073709551615 is not declared in metadata.
[error] Open file mmap stream error.
[error] [Context] Cannot open_mmap_trace of format ctf.
[error] Error adding trace
[warning] [Context] Cannot open_trace of format lttng-live at path net://localhost:50758/host/ci-node-standalone-amd64-02/trace.
[warning] [Context] cannot open trace "net://localhost:50758/host/ci-node-standalone-amd64-02/trace" for reading.
[error] opening trace "net://localhost:50758/host/ci-node-standalone-amd64-02/trace" for reading.
[error] none of the specified trace paths could be opened.
</pre>
<p>Relayd output:<br /><pre>
DEBUG3 - 12:54:40.648163 [31303/31303]: URI string: tcp://localhost:42335 (in uri_parse() at uri.c:324)
DEBUG2 - 12:54:40.648401 [31303/31303]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
DEBUG3 - 12:54:40.648409 [31303/31303]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 42335, data: 0 (in uri_parse() at uri.c:538)
DEBUG3 - 12:54:40.648415 [31303/31303]: URI string: tcp://localhost:38120 (in uri_parse() at uri.c:324)
DEBUG2 - 12:54:40.648436 [31303/31303]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
DEBUG3 - 12:54:40.648439 [31303/31303]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 38120, data: 0 (in uri_parse() at uri.c:538)
DEBUG3 - 12:54:40.648443 [31303/31303]: URI string: tcp://localhost:50758 (in uri_parse() at uri.c:324)
DEBUG2 - 12:54:40.648458 [31303/31303]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
DEBUG3 - 12:54:40.648461 [31303/31303]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 50758, data: 0 (in uri_parse() at uri.c:538)
DEBUG1 - 12:54:40.648466 [31303/31303]: Signal handler set for SIGTERM, SIGUSR1, SIGPIPE and SIGINT (in set_signal_handler() at main.c:649)
DEBUG1 - 12:54:40.648470 [31303/31303]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
DEBUG1 - 12:54:40.648499 [31303/31303]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547)
DEBUG3 - 12:54:40.648567 [31303/31303]: Created hashtable size 4 at 0x9faab0 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:40.648577 [31303/31303]: Created hashtable size 4 at 0x9fae60 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:40.648581 [31303/31303]: Created hashtable size 4 at 0x9fb230 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:40.648640 [31303/31306]: [thread] Relay dispatcher started (in relay_thread_dispatcher() at main.c:962)
DEBUG1 - 12:54:40.648747 [31303/31306]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:40.648755 [31303/31306]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:989)
DEBUG1 - 12:54:40.648672 [31303/31305]: [thread] Manage health check started (in thread_manage_health() at health-relayd.c:239)
DEBUG1 - 12:54:40.648814 [31303/31303]: epoll set max size is 821166 (in compat_epoll_set_max_size() at compat-epoll.c:296)
DEBUG1 - 12:54:40.648706 [31303/31307]: [thread] Relay worker started (in relay_thread_worker() at main.c:2445)
DEBUG3 - 12:54:40.648883 [31303/31307]: Created hashtable size 4 at 0x7fe1940008e0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:40.648804 [31303/31308]: [thread] Relay listener started (in relay_thread_listener() at main.c:771)
DEBUG3 - 12:54:40.648894 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG3 - 12:54:40.649500 [31303/31305]: Creating LTTng run directory: /var/run/lttng (in create_lttng_rundir_with_perm() at health-relayd.c:94)
DEBUG3 - 12:54:40.649528 [31303/31305]: Creating LTTng run directory: /var/run/lttng/relayd (in create_lttng_rundir_with_perm() at health-relayd.c:94)
DEBUG1 - 12:54:40.649676 [31303/31309]: [thread] Live viewer relay dispatcher started (in thread_dispatcher() at live.c:647)
DEBUG1 - 12:54:40.649690 [31303/31309]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:40.649696 [31303/31309]: Woken up but nothing in the live-viewer relay command queue (in thread_dispatcher() at live.c:675)
DEBUG1 - 12:54:40.650092 [31303/31310]: [thread] Live viewer relay worker started (in thread_worker() at live.c:1932)
DEBUG1 - 12:54:40.650186 [31303/31308]: Listening on sock 14 (in relay_socket_create() at main.c:739)
DEBUG1 - 12:54:40.650222 [31303/31308]: Listening on sock 15 (in relay_socket_create() at main.c:739)
DEBUG1 - 12:54:40.650238 [31303/31308]: Listener accepting connections (in relay_thread_listener() at main.c:817)
DEBUG3 - 12:54:40.650623 [31303/31310]: Created hashtable size 4 at 0x7fe17c0008e0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:40.650641 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
Warning: No tracing group detected
DEBUG1 - 12:54:40.650899 [31303/31305]: Health check ready (in thread_manage_health() at health-relayd.c:310)
DEBUG1 - 12:54:40.650920 [31303/31311]: [thread] Relay live listener started (in thread_listener() at live.c:488)
DEBUG1 - 12:54:40.650958 [31303/31311]: Listening on sock 18 for live (in init_socket() at live.c:455)
DEBUG1 - 12:54:40.650975 [31303/31311]: Listener accepting live viewers connections (in thread_listener() at live.c:520)
DEBUG1 - 12:54:41.802814 [31303/31308]: Relay new connection received (in relay_thread_listener() at main.c:835)
DEBUG1 - 12:54:41.802850 [31303/31308]: Relay control connection accepted, socket 20 (in relay_thread_listener() at main.c:880)
DEBUG1 - 12:54:41.802870 [31303/31308]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.802877 [31303/31308]: Listener accepting connections (in relay_thread_listener() at main.c:817)
DEBUG1 - 12:54:41.802891 [31303/31306]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.802901 [31303/31306]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.802908 [31303/31306]: Dispatching request waiting on sock 20 (in relay_thread_dispatcher() at main.c:995)
DEBUG1 - 12:54:41.802936 [31303/31306]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:989)
DEBUG1 - 12:54:41.802971 [31303/31307]: Connection socket 20 added (in relay_thread_worker() at main.c:2535)
DEBUG3 - 12:54:41.802989 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:41.803024 [31303/31307]: Version check done using protocol 2.9 (in relay_send_version() at main.c:1632)
DEBUG3 - 12:54:41.803033 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG3 - 12:54:41.803137 [31303/31307]: Created hashtable size 4 at 0x7fe194000fc0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.803154 [31303/31307]: Created session 1 (in relay_create_session() at main.c:1105)
DEBUG3 - 12:54:41.803171 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:41.803508 [31303/31308]: Relay new connection received (in relay_thread_listener() at main.c:835)
DEBUG1 - 12:54:41.803543 [31303/31308]: Relay data connection accepted, socket 21 (in relay_thread_listener() at main.c:874)
DEBUG1 - 12:54:41.803560 [31303/31308]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.803566 [31303/31308]: Listener accepting connections (in relay_thread_listener() at main.c:817)
DEBUG1 - 12:54:41.803578 [31303/31306]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.803584 [31303/31306]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.803590 [31303/31306]: Dispatching request waiting on sock 21 (in relay_thread_dispatcher() at main.c:995)
DEBUG1 - 12:54:41.803605 [31303/31306]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:989)
DEBUG1 - 12:54:41.803621 [31303/31307]: Connection socket 21 added (in relay_thread_worker() at main.c:2535)
DEBUG3 - 12:54:41.803634 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:41.813698 [31303/31311]: Relay new viewer connection received (in thread_listener() at live.c:537)
DEBUG1 - 12:54:41.813733 [31303/31311]: Relay viewer connection accepted socket 22 (in thread_listener() at live.c:573)
DEBUG1 - 12:54:41.813751 [31303/31311]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.813759 [31303/31311]: Listener accepting live viewers connections (in thread_listener() at live.c:520)
DEBUG1 - 12:54:41.813772 [31303/31309]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.813781 [31303/31309]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.813805 [31303/31309]: Dispatching viewer request waiting on sock 22 (in thread_dispatcher() at live.c:681)
DEBUG1 - 12:54:41.813838 [31303/31309]: Woken up but nothing in the live-viewer relay command queue (in thread_dispatcher() at live.c:675)
DEBUG1 - 12:54:41.813876 [31303/31310]: Connection socket 22 added to poll (in thread_worker() at live.c:2018)
DEBUG3 - 12:54:41.813899 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:41.813915 [31303/31310]: Viewer is establishing a connection to the relayd. (in viewer_connect() at live.c:735)
DEBUG1 - 12:54:41.813943 [31303/31310]: Version check done using protocol 2.4 (in viewer_connect() at live.c:797)
DEBUG3 - 12:54:41.813951 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:41.813992 [31303/31310]: List sessions received (in viewer_list_sessions() at live.c:823)
DEBUG3 - 12:54:41.814031 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:41.830198 [31303/31307]: CTF Trace path /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit not found (in ctf_trace_get_by_path_or_create() at ctf-trace.c:152)
DEBUG1 - 12:54:41.830220 [31303/31307]: Created ctf_trace 1 with path: /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit (in ctf_trace_create() at ctf-trace.c:130)
DEBUG3 - 12:54:41.830234 [31303/31307]: Created hashtable size 4 at 0x7fe1940017a0 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.830450 [31303/31307]: Tracefile /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/channel0_0 created (in stream_create() at stream.c:148)
DEBUG1 - 12:54:41.830463 [31303/31307]: Relay new stream added channel0_0 with ID 1 (in stream_create() at stream.c:174)
DEBUG3 - 12:54:41.830489 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG3 - 12:54:41.830589 [31303/31307]: Created hashtable size 4 at 0x7fe194001f70 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.830639 [31303/31307]: Tracefile /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/channel0_1 created (in stream_create() at stream.c:148)
DEBUG1 - 12:54:41.830648 [31303/31307]: Relay new stream added channel0_1 with ID 2 (in stream_create() at stream.c:174)
DEBUG3 - 12:54:41.830668 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG3 - 12:54:41.831823 [31303/31307]: Created hashtable size 4 at 0x7fe194002650 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.831930 [31303/31307]: Tracefile /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/metadata created (in stream_create() at stream.c:148)
DEBUG1 - 12:54:41.831942 [31303/31307]: Relay new stream added metadata with ID 3 (in stream_create() at stream.c:174)
DEBUG3 - 12:54:41.831967 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:41.832040 [31303/31307]: Relay receiving streams_sent (in relay_streams_sent() at main.c:2074)
DEBUG3 - 12:54:41.832059 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG2 - 12:54:41.839480 [31303/31307]: Relay receiving metadata, waiting for 3773 bytes (in relay_recv_metadata() at main.c:1530)
DEBUG1 - 12:54:41.852011 [31303/31310]: Viewer create session received (in viewer_create_session() at live.c:1733)
DEBUG3 - 12:54:41.852050 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:41.852090 [31303/31310]: Session find by ID 1 id found (in session_get_by_id() at session.c:122)
DEBUG1 - 12:54:41.852101 [31303/31310]: Attach session ID 1 received (in viewer_attach_session() at live.c:1046)
DEBUG1 - 12:54:41.852125 [31303/31310]: Relay viewer stream 1 not found (in viewer_stream_get_by_id() at viewer-stream.c:228)
DEBUG1 - 12:54:41.852138 [31303/31310]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:41.852145 [31303/31310]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:41.852163 [31303/31310]: Relay viewer stream 2 not found (in viewer_stream_get_by_id() at viewer-stream.c:228)
DEBUG1 - 12:54:41.852170 [31303/31310]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:41.852174 [31303/31310]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:41.852179 [31303/31310]: Relay viewer stream 3 not found (in viewer_stream_get_by_id() at viewer-stream.c:228)
DEBUG1 - 12:54:41.852185 [31303/31310]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:41.852189 [31303/31310]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:41.852209 [31303/31310]: Sending stream 2 to viewer (in send_viewer_streams() at live.c:250)
DEBUG1 - 12:54:41.852223 [31303/31310]: Sending stream 3 to viewer (in send_viewer_streams() at live.c:250)
DEBUG1 - 12:54:41.852231 [31303/31310]: Sending stream 1 to viewer (in send_viewer_streams() at live.c:250)
DEBUG3 - 12:54:41.852239 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG2 - 12:54:41.876009 [31303/31307]: Relay metadata written. Updated metadata_received 4096 (in relay_recv_metadata() at main.c:1569)
DEBUG1 - 12:54:41.876025 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:41.876032 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:41.876039 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:41.892033 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600)
DEBUG1 - 12:54:41.892098 [31303/31310]: Sent 4096 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709)
DEBUG1 - 12:54:41.892107 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711)
DEBUG3 - 12:54:41.892114 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:41.932004 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600)
DEBUG1 - 12:54:41.932044 [31303/31310]: Sent 0 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709)
DEBUG1 - 12:54:41.932053 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711)
DEBUG3 - 12:54:41.932059 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:41.933196 [31303/31310]: Viewer get next index (in viewer_get_next_index() at live.c:1286)
DEBUG1 - 12:54:41.933220 [31303/31310]: get next index metadata check: recv 4096 sent 4096 (in viewer_get_next_index() at live.c:1433)
DEBUG1 - 12:54:41.933239 [31303/31310]: Index 0 for stream 1 sent (in viewer_get_next_index() at live.c:1454)
DEBUG3 - 12:54:41.933246 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:42.335059 [31303/31310]: Viewer get next index (in viewer_get_next_index() at live.c:1286)
DEBUG1 - 12:54:42.335353 [31303/31310]: get next index metadata check: recv 4096 sent 4096 (in viewer_get_next_index() at live.c:1433)
DEBUG1 - 12:54:42.335555 [31303/31310]: Index 0 for stream 1 sent (in viewer_get_next_index() at live.c:1454)
DEBUG3 - 12:54:42.335636 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG3 - 12:54:42.398087 [31303/31307]: Receiving data of size 84 for stream id 1 seqnum 0 (in relay_process_data() at main.c:2288)
DEBUG1 - 12:54:42.398753 [31303/31307]: handle_index_data: stream 1 net_seq_num 0 data offset 0 (in handle_index_data() at main.c:2181)
DEBUG3 - 12:54:42.398870 [31303/31307]: Finding index for stream id 1 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133)
DEBUG2 - 12:54:42.399049 [31303/31307]: Creating relay index for stream id 1 and seqnum 0 (in relay_index_create() at index.c:44)
DEBUG2 - 12:54:42.399136 [31303/31307]: Adding relay index with stream id 1 and seqnum 0 (in relay_index_add_unique() at index.c:81)
DEBUG2 - 12:54:42.399223 [31303/31307]: Index found or created in HT for stream ID 1 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165)
DEBUG1 - 12:54:42.400070 [31303/31307]: utils_unlink_stream_file /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/index/channel0_0.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
DEBUG2 - 12:54:42.400745 [31303/31307]: Relay wrote 84 bytes to tracefile for stream id 1 (in relay_process_data() at main.c:2359)
DEBUG1 - 12:54:42.400928 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.400984 [31303/31307]: stream put stream id 1 refcount 4 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.401048 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.401172 [31303/31307]: Relay receiving index (in relay_recv_index() at main.c:1957)
DEBUG3 - 12:54:42.401262 [31303/31307]: Finding index for stream id 1 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133)
DEBUG2 - 12:54:42.401323 [31303/31307]: Index found or created in HT for stream ID 1 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165)
DEBUG2 - 12:54:42.401381 [31303/31307]: Writing index for stream ID 1 and seq num 0 on fd 27 (in relay_index_try_flush() at index.c:300)
DEBUG2 - 12:54:42.401464 [31303/31307]: index put for stream id 1 and seqnum 0 refcount 1 (in relay_index_put() at index.c:259)
DEBUG1 - 12:54:42.401551 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.401598 [31303/31307]: stream put stream id 1 refcount 4 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.402302 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.402407 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.402715 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG3 - 12:54:42.403456 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG3 - 12:54:42.403637 [31303/31307]: Receiving data of size 10393 for stream id 2 seqnum 0 (in relay_process_data() at main.c:2288)
DEBUG1 - 12:54:42.403707 [31303/31307]: handle_index_data: stream 2 net_seq_num 0 data offset 0 (in handle_index_data() at main.c:2181)
DEBUG3 - 12:54:42.403763 [31303/31307]: Finding index for stream id 2 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133)
DEBUG2 - 12:54:42.403830 [31303/31307]: Creating relay index for stream id 2 and seqnum 0 (in relay_index_create() at index.c:44)
DEBUG2 - 12:54:42.403894 [31303/31307]: Adding relay index with stream id 2 and seqnum 0 (in relay_index_add_unique() at index.c:81)
DEBUG2 - 12:54:42.403960 [31303/31307]: Index found or created in HT for stream ID 2 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165)
DEBUG1 - 12:54:42.404220 [31303/31307]: utils_unlink_stream_file /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/index/channel0_1.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
DEBUG2 - 12:54:42.405246 [31303/31307]: Relay wrote 10393 bytes to tracefile for stream id 2 (in relay_process_data() at main.c:2359)
DEBUG1 - 12:54:42.405384 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.405434 [31303/31307]: stream put stream id 2 refcount 4 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.405490 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.405594 [31303/31307]: Relay receiving index (in relay_recv_index() at main.c:1957)
DEBUG3 - 12:54:42.406109 [31303/31307]: Finding index for stream id 2 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133)
DEBUG2 - 12:54:42.406174 [31303/31307]: Index found or created in HT for stream ID 2 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165)
DEBUG2 - 12:54:42.406230 [31303/31307]: Writing index for stream ID 2 and seq num 0 on fd 28 (in relay_index_try_flush() at index.c:300)
DEBUG2 - 12:54:42.406312 [31303/31307]: index put for stream id 2 and seqnum 0 refcount 1 (in relay_index_put() at index.c:259)
DEBUG1 - 12:54:42.406392 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.406440 [31303/31307]: stream put stream id 2 refcount 4 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.406531 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.406578 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.406917 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.418993 [31303/31307]: Init streams for data pending (in relay_begin_data_pending() at main.c:1793)
DEBUG1 - 12:54:42.419157 [31303/31307]: Set begin data pending flag to stream 2 (in relay_begin_data_pending() at main.c:1833)
DEBUG1 - 12:54:42.419217 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.419267 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.419324 [31303/31307]: Set begin data pending flag to stream 3 (in relay_begin_data_pending() at main.c:1833)
DEBUG1 - 12:54:42.419369 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.419413 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.419462 [31303/31307]: Set begin data pending flag to stream 1 (in relay_begin_data_pending() at main.c:1833)
DEBUG1 - 12:54:42.419506 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.419550 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.419709 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.420443 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651)
DEBUG1 - 12:54:42.420574 [31303/31307]: Data pending for stream id 1 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685)
DEBUG1 - 12:54:42.420635 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.420682 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.420816 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.421372 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651)
DEBUG1 - 12:54:42.421472 [31303/31307]: Data pending for stream id 2 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685)
DEBUG1 - 12:54:42.421526 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.421572 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.421694 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.422269 [31303/31307]: Checking quiescent state on control socket (in relay_quiescent_control() at main.c:1730)
DEBUG1 - 12:54:42.422381 [31303/31307]: Relay quiescent control pending flag set to 3 (in relay_quiescent_control() at main.c:1759)
DEBUG1 - 12:54:42.422434 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.422480 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.422603 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.423119 [31303/31307]: End data pending command (in relay_end_data_pending() at main.c:1872)
DEBUG1 - 12:54:42.423228 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.423278 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.423330 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.423374 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.423422 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.423466 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.423592 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.526657 [31303/31307]: Init streams for data pending (in relay_begin_data_pending() at main.c:1793)
DEBUG1 - 12:54:42.526860 [31303/31307]: Set begin data pending flag to stream 2 (in relay_begin_data_pending() at main.c:1833)
DEBUG1 - 12:54:42.526923 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.526977 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.527037 [31303/31307]: Set begin data pending flag to stream 3 (in relay_begin_data_pending() at main.c:1833)
DEBUG1 - 12:54:42.527084 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.527129 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.527178 [31303/31307]: Set begin data pending flag to stream 1 (in relay_begin_data_pending() at main.c:1833)
DEBUG1 - 12:54:42.527223 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.527266 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.527449 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.528088 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651)
DEBUG1 - 12:54:42.528206 [31303/31307]: Data pending for stream id 1 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685)
DEBUG1 - 12:54:42.528265 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.528312 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.528446 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.529116 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651)
DEBUG1 - 12:54:42.529212 [31303/31307]: Data pending for stream id 2 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685)
DEBUG1 - 12:54:42.529260 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.529304 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.529419 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.529951 [31303/31307]: Checking quiescent state on control socket (in relay_quiescent_control() at main.c:1730)
DEBUG1 - 12:54:42.530050 [31303/31307]: Relay quiescent control pending flag set to 3 (in relay_quiescent_control() at main.c:1759)
DEBUG1 - 12:54:42.530098 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.530140 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.530261 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.530662 [31303/31307]: End data pending command (in relay_end_data_pending() at main.c:1872)
DEBUG1 - 12:54:42.530757 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.530801 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.530967 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.531013 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.531058 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.531098 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.531233 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG2 - 12:54:42.537906 [31303/31307]: Relay receiving metadata, waiting for 49 bytes (in relay_recv_metadata() at main.c:1530)
DEBUG2 - 12:54:42.920021 [31303/31307]: Relay metadata written. Updated metadata_received 8192 (in relay_recv_metadata() at main.c:1569)
DEBUG1 - 12:54:42.920178 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.920242 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.920314 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.920451 [31303/31307]: Close stream received (in relay_close_stream() at main.c:1248)
DEBUG1 - 12:54:42.920622 [31303/31307]: Trying to close stream 3 (in try_stream_close() at stream.c:351)
DEBUG1 - 12:54:42.920741 [31303/31307]: Succeeded in closing stream 3 (in try_stream_close() at stream.c:428)
DEBUG1 - 12:54:42.920797 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.920843 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.920910 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.920954 [31303/31307]: stream put stream id 3 refcount 2 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.921143 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.120421 [31303/31307]: Close stream received (in relay_close_stream() at main.c:1248)
DEBUG1 - 12:54:42.120444 [31303/31307]: Trying to close stream 1 (in try_stream_close() at stream.c:351)
DEBUG1 - 12:54:42.120455 [31303/31307]: Succeeded in closing stream 1 (in try_stream_close() at stream.c:428)
DEBUG1 - 12:54:42.120460 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.120465 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.120470 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.120474 [31303/31307]: stream put stream id 1 refcount 2 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.120511 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.120668 [31303/31307]: Close stream received (in relay_close_stream() at main.c:1248)
DEBUG1 - 12:54:42.120682 [31303/31307]: Trying to close stream 2 (in try_stream_close() at stream.c:351)
DEBUG1 - 12:54:42.120689 [31303/31307]: Succeeded in closing stream 2 (in try_stream_close() at stream.c:428)
DEBUG1 - 12:54:42.120694 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.120698 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.120703 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.120707 [31303/31307]: stream put stream id 2 refcount 2 (in stream_put() at stream.c:340)
DEBUG3 - 12:54:42.120735 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.133819 [31303/31310]: Viewer get next index (in viewer_get_next_index() at live.c:1286)
DEBUG1 - 12:54:42.133851 [31303/31310]: Index opening file /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/index/channel0_0.idx in read only (in lttng_index_file_open() at index.c:223)
DEBUG1 - 12:54:42.133884 [31303/31310]: Sending viewer index for stream 1 offset 0 (in viewer_get_next_index() at live.c:1414)
DEBUG1 - 12:54:42.133901 [31303/31310]: get next index metadata check: recv 8192 sent 4096 (in viewer_get_next_index() at live.c:1433)
DEBUG1 - 12:54:42.133924 [31303/31310]: Index 1 for stream 1 sent (in viewer_get_next_index() at live.c:1454)
DEBUG3 - 12:54:42.133932 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:42.133991 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600)
DEBUG1 - 12:54:42.134023 [31303/31310]: Sent 4096 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709)
DEBUG1 - 12:54:42.134030 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711)
DEBUG1 - 12:54:42.134044 [31303/31310]: stream put for stream id 3 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.134050 [31303/31310]: stream put stream id 3 refcount 1 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.134056 [31303/31310]: Releasing stream id 3 (in stream_release() at stream.c:293)
DEBUG3 - 12:54:42.134086 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:42.152037 [31303/31307]: Control connection closed with 20 (in relay_thread_close_connection() at main.c:2429)
DEBUG1 - 12:54:42.152065 [31303/31307]: closing session 1: is conn already closed 0 (in session_close() at session.c:196)
DEBUG2 - 12:54:42.152081 [31303/31307]: Relay connection by sock 20 not found (in connection_get_by_sock() at connection.c:56)
DEBUG3 - 12:54:42.152088 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.152100 [31303/31307]: Socket 21 did an orderly shutdown (in relay_process_data() at main.c:2267)
DEBUG1 - 12:54:42.152131 [31303/31307]: Data connection closed with 21 (in relay_thread_close_connection() at main.c:2429)
DEBUG3 - 12:54:42.152141 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480)
DEBUG1 - 12:54:42.172008 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600)
DEBUG1 - 12:54:42.172035 [31303/31310]: Relay viewer stream 3 not found (in viewer_stream_get_by_id() at viewer-stream.c:228)
DEBUG1 - 12:54:42.172042 [31303/31310]: Client requested metadata of unknown stream id 3 (in viewer_get_metadata() at live.c:1623)
DEBUG1 - 12:54:42.172061 [31303/31310]: Sent 0 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709)
DEBUG1 - 12:54:42.172067 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711)
DEBUG3 - 12:54:42.172073 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
DEBUG1 - 12:54:42.173400 [31303/31310]: Viewer control conn closed with 22 (in thread_worker() at live.c:2043)
DEBUG1 - 12:54:42.173425 [31303/31310]: stream put for stream id 2 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.173431 [31303/31310]: stream put stream id 2 refcount 1 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.173436 [31303/31310]: Releasing stream id 2 (in stream_release() at stream.c:293)
DEBUG1 - 12:54:42.173454 [31303/31310]: stream put for stream id 1 (in stream_put() at stream.c:323)
DEBUG1 - 12:54:42.173459 [31303/31310]: stream put stream id 1 refcount 1 (in stream_put() at stream.c:340)
DEBUG1 - 12:54:42.173464 [31303/31310]: Releasing stream id 1 (in stream_release() at stream.c:293)
DEBUG3 - 12:54:42.173476 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
</pre></p>
<p>Sessiond log:<br /><pre>
libust[31312/31312]: LTT : ltt ring buffer client "relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at lttng-ring-buffer-metadata-client.h:349)
libust[31312/31312]: LTT : ltt ring buffer client "relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at lttng-ring-buffer-client.h:824)
libust[31312/31312]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at lttng-ring-buffer-client.h:824)
libust[31312/31312]: LTT : ltt ring buffer client "relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at lttng-ring-buffer-client.h:824)
libust[31312/31312]: LTT : ltt ring buffer client "relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at lttng-ring-buffer-client.h:824)
DEBUG3 - 12:54:41.657863 [31312/31312]: Agent TCP port set to non default: 58367 (in set_option() at main.c:4898)
DEBUG1 - 12:54:41.658213 [31313/31313]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:541)
DEBUG1 - 12:54:41.658333 [31313/31313]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:602)
DEBUG1 - 12:54:41.658496 [31312/31312]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
DEBUG3 - 12:54:41.658653 [31312/31312]: Creating LTTng run directory: /var/run/lttng (in create_lttng_rundir() at main.c:5268)
DEBUG1 - 12:54:41.658652 [31312/31314]: [ht-thread] startup. (in thread_ht_cleanup() at ht-cleanup.c:101)
DEBUG2 - 12:54:41.658739 [31312/31312]: Kernel consumer err path: /var/run/lttng/kconsumerd/error (in main() at main.c:5735)
DEBUG2 - 12:54:41.658749 [31312/31312]: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command (in main() at main.c:5737)
DEBUG1 - 12:54:41.658746 [31312/31314]: epoll set max size is 821166 (in compat_epoll_set_max_size() at compat-epoll.c:296)
DEBUG1 - 12:54:41.658778 [31312/31312]: Client socket path /var/run/lttng/client-lttng-sessiond (in main() at main.c:5817)
DEBUG1 - 12:54:41.658786 [31312/31312]: Application socket path /var/run/lttng/lttng-ust-sock-7 (in main() at main.c:5818)
DEBUG1 - 12:54:41.658791 [31312/31312]: Application wait path /lttng-ust-wait-7 (in main() at main.c:5819)
DEBUG1 - 12:54:41.658796 [31312/31312]: LTTng run directory path: /var/run/lttng (in main() at main.c:5820)
DEBUG3 - 12:54:41.658797 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG2 - 12:54:41.658837 [31312/31312]: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error (in main() at main.c:5839)
DEBUG2 - 12:54:41.658847 [31312/31312]: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command (in main() at main.c:5841)
DEBUG2 - 12:54:41.658868 [31312/31312]: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error (in main() at main.c:5860)
DEBUG2 - 12:54:41.658876 [31312/31312]: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command (in main() at main.c:5862)
DEBUG3 - 12:54:41.659029 [31312/31312]: Created hashtable size 4 at 0x17d1250 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.659047 [31312/31312]: Created hashtable size 4 at 0x17d1690 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.659055 [31312/31312]: Created hashtable size 4 at 0x17d1ad0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.659063 [31312/31312]: Created hashtable size 4 at 0x17d27c0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.659069 [31312/31312]: Creating consumer directory: /var/run/lttng/kconsumerd (in set_consumer_sockets() at main.c:5310)
Warning: No tracing group detected
modprobe: FATAL: Module lttng-ring-buffer-client-discard not found in directory /lib/modules/4.4.0-97-generic
Error: Unable to load required module lttng-ring-buffer-client-discard
DEBUG1 - 12:54:41.663308 [31312/31312]: Failed to open /proc/lttng (in init_kernel_tracer() at main.c:2718)
Warning: No kernel tracer available
DEBUG2 - 12:54:41.663328 [31312/31312]: Creating consumer directory: /var/run/lttng/ustconsumerd64 (in set_consumer_sockets() at main.c:5310)
DEBUG2 - 12:54:41.663484 [31312/31312]: Creating consumer directory: /var/run/lttng/ustconsumerd32 (in set_consumer_sockets() at main.c:5310)
DEBUG3 - 12:54:41.663628 [31312/31312]: Session daemon client socket 15 and application socket 16 created (in init_daemon_socket() at main.c:5176)
DEBUG1 - 12:54:41.663697 [31312/31312]: All permissions are set (in set_permissions() at main.c:5256)
DEBUG3 - 12:54:41.663741 [31312/31312]: Created hashtable size 4 at 0x17d51b0 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.663749 [31312/31312]: Global buffer per UID registry initialized (in buffer_reg_init_uid_registry() at buffer-registry.c:99)
DEBUG3 - 12:54:41.663757 [31312/31312]: Created hashtable size 4 at 0x17d5560 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.663763 [31312/31312]: Global buffer per PID registry initialized (in buffer_reg_init_pid_registry() at buffer-registry.c:228)
DEBUG1 - 12:54:41.663770 [31312/31312]: Command subsystem initialized (in cmd_init() at cmd.c:4015)
DEBUG1 - 12:54:41.663808 [31312/31312]: Pid 31312 written in file /var/run/lttng/lttng-sessiond.pid (in utils_create_pid_file() at utils.c:507)
DEBUG1 - 12:54:41.663829 [31312/31312]: Pid 58367 written in file /var/run/lttng/agent.port (in utils_create_pid_file() at utils.c:507)
DEBUG1 - 12:54:41.663905 [31312/31312]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547)
DEBUG1 - 12:54:41.663995 [31312/31318]: [thread] Manage health check started (in thread_manage_health() at main.c:4159)
DEBUG1 - 12:54:41.664025 [31312/31319]: [thread] Manage client started (in thread_manage_clients() at main.c:4350)
DEBUG1 - 12:54:41.675072 [31312/31322]: [thread] Manage application started (in thread_manage_apps() at main.c:1555)
DEBUG1 - 12:54:41.672333 [31312/31320]: [thread] Dispatch UST command started (in thread_dispatch_ust_registration() at main.c:1869)
DEBUG1 - 12:54:41.675769 [31312/31320]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.675780 [31312/31320]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1896)
DEBUG1 - 12:54:41.664162 [31312/31321]: [thread] Manage application registration started (in thread_registration_apps() at main.c:2114)
DEBUG1 - 12:54:41.675980 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.676028 [31312/31323]: [ust-thread] Manage application notify command (in ust_thread_manage_notify() at ust-thread.c:40)
DEBUG1 - 12:54:41.676028 [31312/31321]: Notifying applications of session daemon state: 1 (in notify_ust_apps() at main.c:804)
DEBUG1 - 12:54:41.676157 [31312/31318]: Health check ready (in thread_manage_health() at main.c:4221)
DEBUG1 - 12:54:41.676079 [31312/31321]: Got the wait shm fd 29 (in get_wait_shm() at shm.c:115)
DEBUG1 - 12:54:41.676213 [31312/31321]: Futex wait update active 1 (in futex_wait_update() at futex.c:65)
DEBUG1 - 12:54:41.676220 [31312/31321]: Accepting application registration (in thread_registration_apps() at main.c:2151)
DEBUG1 - 12:54:41.676236 [31312/31322]: Apps thread polling (in thread_manage_apps() at main.c:1585)
DEBUG1 - 12:54:41.676250 [31312/31324]: [agent-thread] Manage agent application registration. (in agent_thread_manage_registration() at agent-thread.c:236)
DEBUG3 - 12:54:41.676265 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG1 - 12:54:41.676289 [31312/31325]: [thread] Thread manage kernel started (in thread_manage_kernel() at main.c:1053)
DEBUG3 - 12:54:41.676293 [31312/31324]: URI string: tcp://localhost (in uri_parse() at uri.c:324)
DEBUG1 - 12:54:41.676319 [31312/31326]: [load-session-thread] Load session (in thread_load_session() at load-session-thread.c:91)
DEBUG1 - 12:54:41.676384 [31312/31325]: Updating kernel poll set (in update_kernel_poll() at main.c:888)
DEBUG1 - 12:54:41.676396 [31312/31325]: Thread kernel polling (in thread_manage_kernel() at main.c:1098)
DEBUG2 - 12:54:41.681057 [31312/31324]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
DEBUG3 - 12:54:41.681075 [31312/31324]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 0, data: 0 (in uri_parse() at uri.c:538)
DEBUG1 - 12:54:41.681105 [31312/31324]: [agent-thread] Listening on TCP port 58367 and socket 31 (in init_tcp_socket() at agent-thread.c:119)
DEBUG3 - 12:54:41.681115 [31312/31324]: [agent-thread] Manage agent polling (in agent_thread_manage_registration() at agent-thread.c:263)
DEBUG1 - 12:54:41.686839 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.686883 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.686907 [31312/31319]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4498)
DEBUG1 - 12:54:41.686920 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.686926 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.687356 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.687381 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.687423 [31312/31319]: Processing client command 30 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.687451 [31312/31319]: Waiting for 2 URIs from client ... (in process_client_msg() at main.c:4077)
DEBUG2 - 12:54:41.687479 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:41.687505 [31312/31319]: Created hashtable size 4 at 0x7fab0c008f10 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.687512 [31312/31319]: Allocating ltt_sessions_ht_by_id (in ltt_sessions_ht_alloc() at session.c:153)
DEBUG3 - 12:54:41.687518 [31312/31319]: Created hashtable size 4 at 0x7fab0c009350 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.687527 [31312/31319]: Tracing session trace created with ID 0 by UID 0 GID 0 (in session_create() at session.c:420)
DEBUG2 - 12:54:41.687533 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:41.687557 [31312/31319]: Created hashtable size 4 at 0x7fab0c00e800 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.687563 [31312/31319]: Setting network URI to consumer (in add_uri_to_consumer() at cmd.c:718)
DEBUG3 - 12:54:41.687570 [31312/31319]: Consumer control URI set with port 38120 (in consumer_set_network_uri() at consumer.c:659)
DEBUG3 - 12:54:41.687583 [31312/31319]: Consumer set network uri subdir path ci-node-standalone-amd64-02/ (in consumer_set_network_uri() at consumer.c:722)
DEBUG2 - 12:54:41.687601 [31312/31319]: Consumer subdir set to ci-node-standalone-amd64-02//trace-20171215-125441/ (in consumer_set_subdir() at consumer.c:1097)
DEBUG3 - 12:54:41.687608 [31312/31319]: Append domain trace name to subdir ci-node-standalone-amd64-02//trace-20171215-125441/ (in add_uri_to_consumer() at cmd.c:760)
DEBUG2 - 12:54:41.687613 [31312/31319]: Setting network URI to consumer (in add_uri_to_consumer() at cmd.c:718)
DEBUG3 - 12:54:41.687617 [31312/31319]: Consumer data URI set with port 42335 (in consumer_set_network_uri() at consumer.c:674)
DEBUG1 - 12:54:41.687625 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:41.687640 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.687645 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.696439 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.696469 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.696505 [31312/31319]: Processing client command 6 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.696522 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:41.696528 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:41.696534 [31312/31319]: Creating UST session (in create_ust_session() at main.c:2856)
DEBUG3 - 12:54:41.696547 [31312/31319]: Created hashtable size 4 at 0x7fab0c005ea0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.696555 [31312/31319]: Created hashtable size 4 at 0x7fab0c0062e0 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.696591 [31312/31319]: Created hashtable size 4 at 0x7fab0c006720 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.696597 [31312/31319]: UST trace session create successful (in trace_ust_create_session() at trace-ust.c:320)
DEBUG3 - 12:54:41.696603 [31312/31319]: Copying tracing session consumer output in UST session (in copy_session_consumer() at main.c:2803)
DEBUG3 - 12:54:41.696632 [31312/31319]: Created hashtable size 4 at 0x7fab0c006b60 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.696643 [31312/31319]: Copy session consumer subdir ci-node-standalone-amd64-02//trace-20171215-125441//ust (in copy_session_consumer() at main.c:2821)
DEBUG1 - 12:54:41.696651 [31312/31319]: Spawning consumerd (in spawn_consumerd() at main.c:2491)
DEBUG3 - 12:54:41.696680 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG2 - 12:54:41.697073 [31312/31319]: Consumer pid 31329 (in start_consumerd() at main.c:2676)
DEBUG2 - 12:54:41.697127 [31312/31319]: Spawning consumer control thread (in start_consumerd() at main.c:2679)
DEBUG1 - 12:54:41.697232 [31312/31330]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1227)
DEBUG1 - 12:54:41.698790 [31329/31329]: Using 64-bit UST consumer at: /root/workspace/lttng-ivc-master-modules/arch/x86-64/liburcu_version/master/slave/x86-64-standalone/src/lttng_ivc/runtime/projects_cache/lttng-tools-2.9/install/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2571)
libust[31329/31329]: LTT : ltt ring buffer client "relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at lttng-ring-buffer-metadata-client.h:349)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at lttng-ring-buffer-client.h:824)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at lttng-ring-buffer-client.h:824)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at lttng-ring-buffer-client.h:824)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at lttng-ring-buffer-client.h:824)
DEBUG1 - 12:54:41.700892 [31329/31329]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
DEBUG1 - 12:54:41.701077 [31329/31329]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547)
DEBUG1 - 12:54:41.701314 [31332/31332]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:541)
DEBUG1 - 12:54:41.701399 [31332/31332]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:602)
DEBUG1 - 12:54:41.701521 [31329/31329]: Connecting to error socket /var/run/lttng/ustconsumerd64/error (in main() at lttng-consumerd.c:464)
DEBUG2 - 12:54:41.701593 [31312/31330]: Receiving code from consumer err_sock (in thread_manage_consumer() at main.c:1325)
DEBUG1 - 12:54:41.701698 [31329/31333]: [thread] Manage health check started (in thread_manage_health() at health-consumerd.c:167)
Warning: No tracing group detected
DEBUG1 - 12:54:41.702675 [31329/31333]: epoll set max size is 821166 (in compat_epoll_set_max_size() at compat-epoll.c:296)
DEBUG1 - 12:54:41.702697 [31329/31333]: Health check ready (in thread_manage_health() at health-consumerd.c:240)
DEBUG3 - 12:54:41.707313 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG1 - 12:54:41.802365 [31329/31336]: Thread metadata poll started (in consumer_thread_metadata_poll() at consumer.c:2245)
DEBUG1 - 12:54:41.802399 [31329/31335]: Thread channel poll started (in consumer_thread_channel_poll() at consumer.c:2829)
DEBUG1 - 12:54:41.802429 [31329/31336]: Metadata main loop started (in consumer_thread_metadata_poll() at consumer.c:2261)
DEBUG1 - 12:54:41.802467 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG1 - 12:54:41.802489 [31329/31337]: Updating poll fd array (in update_poll_array() at consumer.c:1085)
DEBUG1 - 12:54:41.802512 [31329/31337]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:41.802492 [31329/31338]: Creating command socket /var/run/lttng/ustconsumerd64/command (in consumer_thread_sessiond_poll() at consumer.c:3097)
DEBUG1 - 12:54:41.802431 [31329/31335]: Channel main loop started (in consumer_thread_channel_poll() at consumer.c:2844)
DEBUG1 - 12:54:41.802558 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:41.802564 [31329/31338]: Sending ready command to lttng-sessiond (in consumer_thread_sessiond_poll() at consumer.c:3110)
DEBUG3 - 12:54:41.802645 [31312/31319]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 12:54:41.802664 [31312/31319]: Setting relayd for session trace (in cmd_setup_relayd() at cmd.c:1014)
DEBUG3 - 12:54:41.802685 [31312/31319]: Relayd connect ... (in relayd_connect() at relayd.c:494)
DEBUG3 - 12:54:41.802783 [31312/31319]: Creating relayd stream socket from URI (in create_connect_relayd() at cmd.c:855)
DEBUG1 - 12:54:41.802795 [31312/31319]: Relayd version check for major.minor 2.9 (in relayd_version_check() at relayd.c:392)
DEBUG3 - 12:54:41.802823 [31312/31319]: Relayd sending command 5 of size 32 (in send_command() at relayd.c:81)
DEBUG3 - 12:54:41.802830 [31312/31319]: Relayd waiting for reply of size 8 (in recv_reply() at relayd.c:101)
DEBUG1 - 12:54:41.802844 [31312/31330]: Consumer command socket ready (fd: 35 (in thread_manage_consumer() at main.c:1358)
DEBUG1 - 12:54:41.802850 [31312/31330]: Consumer metadata socket ready (fd: 36) (in thread_manage_consumer() at main.c:1360)
DEBUG1 - 12:54:41.802870 [31329/31338]: Connection on client_socket (in consumer_thread_sessiond_poll() at consumer.c:3132)
DEBUG1 - 12:54:41.802889 [31329/31338]: Metadata connection on client_socket (in set_metadata_socket() at consumer.c:3058)
DEBUG2 - 12:54:41.803053 [31312/31319]: Relayd version is compatible, using protocol version 2.9 (in relayd_version_check() at relayd.c:440)
DEBUG1 - 12:54:41.803070 [31312/31319]: Relayd create session (in relayd_create_session() at relayd.c:189)
DEBUG3 - 12:54:41.803096 [31312/31319]: Relayd sending command 2 of size 351 (in send_command() at relayd.c:81)
DEBUG3 - 12:54:41.803104 [31312/31319]: Relayd waiting for reply of size 12 (in recv_reply() at relayd.c:101)
DEBUG1 - 12:54:41.803188 [31312/31319]: Relayd session created with id 1 (in relayd_create_session() at relayd.c:227)
DEBUG3 - 12:54:41.803197 [31312/31319]: Sending relayd sock info to consumer on 35 (in consumer_send_relayd_socket() at consumer.c:1033)
DEBUG1 - 12:54:41.803222 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.803251 [31329/31338]: Consumer adding relayd socket (idx: 2) (in consumer_add_relayd_socket() at consumer.c:3359)
DEBUG3 - 12:54:41.803296 [31312/31319]: Sending relayd socket file descriptor to consumer (in consumer_send_relayd_socket() at consumer.c:1039)
DEBUG1 - 12:54:41.803343 [31329/31338]: Consumer control socket created successfully with net idx 2 (fd: -1) (in consumer_add_relayd_socket() at consumer.c:3489)
DEBUG2 - 12:54:41.803362 [31312/31319]: Consumer relayd socket sent (in consumer_send_relayd_socket() at consumer.c:1045)
DEBUG3 - 12:54:41.803379 [31312/31319]: Relayd closing socket 37 (in relayd_close() at relayd.c:525)
DEBUG3 - 12:54:41.803393 [31312/31319]: Relayd connect ... (in relayd_connect() at relayd.c:494)
DEBUG3 - 12:54:41.803451 [31312/31319]: Creating relayd data socket from URI (in create_connect_relayd() at cmd.c:866)
DEBUG3 - 12:54:41.803463 [31312/31319]: Sending relayd sock info to consumer on 35 (in consumer_send_relayd_socket() at consumer.c:1033)
DEBUG1 - 12:54:41.803490 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.803501 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.803520 [31329/31338]: Consumer adding relayd socket (idx: 2) (in consumer_add_relayd_socket() at consumer.c:3359)
DEBUG3 - 12:54:41.803536 [31312/31319]: Sending relayd socket file descriptor to consumer (in consumer_send_relayd_socket() at consumer.c:1039)
DEBUG1 - 12:54:41.803600 [31329/31338]: Consumer data socket created successfully with net idx 2 (fd: -1) (in consumer_add_relayd_socket() at consumer.c:3489)
DEBUG2 - 12:54:41.803662 [31312/31319]: Consumer relayd socket sent (in consumer_send_relayd_socket() at consumer.c:1045)
DEBUG3 - 12:54:41.803671 [31312/31319]: Relayd closing socket 37 (in relayd_close() at relayd.c:525)
DEBUG1 - 12:54:41.803684 [31312/31319]: Enable event command for event 'tp:tptest' (in _cmd_enable_event() at cmd.c:1822)
DEBUG2 - 12:54:41.803694 [31312/31319]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
DEBUG1 - 12:54:41.803704 [31312/31319]: Enabling channel for session trace (in cmd_enable_channel() at cmd.c:1317)
DEBUG2 - 12:54:41.803709 [31312/31319]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
DEBUG3 - 12:54:41.803721 [31312/31319]: Created hashtable size 4 at 0x7fab0c007240 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.803729 [31312/31319]: Created hashtable size 4 at 0x7fab0c007610 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.803734 [31312/31319]: Trace UST channel channel0 created (in trace_ust_create_channel() at trace-ust.c:391)
DEBUG2 - 12:54:41.803741 [31312/31319]: Channel channel0 is being created for UST with buffer 1 and id 0 (in channel_ust_create() at channel.c:413)
DEBUG2 - 12:54:41.803747 [31312/31319]: UST app adding channel channel0 to UST domain for session id 0 (in ust_app_create_channel_glb() at ust-app.c:4074)
DEBUG2 - 12:54:41.803757 [31312/31319]: Channel channel0 created successfully (in channel_ust_create() at channel.c:448)
DEBUG2 - 12:54:41.803763 [31312/31319]: Trace UST channel channel0 found by name (in trace_ust_find_channel_by_name() at trace-ust.c:191)
DEBUG2 - 12:54:41.803770 [31312/31319]: Trace UST event tp:tptest NOT found (in trace_ust_find_event() at trace-ust.c:234)
DEBUG2 - 12:54:41.803776 [31312/31319]: Trace UST event tp:tptest, loglevel (0,-1) created (in trace_ust_create_event() at trace-ust.c:508)
DEBUG1 - 12:54:41.803781 [31312/31319]: UST app creating event tp:tptest for all apps for session id 0 (in ust_app_create_event_glb() at ust-app.c:4258)
DEBUG1 - 12:54:41.803788 [31312/31319]: Event UST tp:tptest created in channel channel0 (in event_ust_enable_tracepoint() at event.c:236)
DEBUG1 - 12:54:41.803799 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:41.803820 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.803826 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.804241 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.819907 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.819960 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.820003 [31312/31319]: Processing client command 16 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.820014 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:41.820020 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:41.820031 [31312/31319]: Starting all UST traces (in ust_app_start_trace_all() at ust-app.c:4859)
DEBUG1 - 12:54:41.820036 [31312/31319]: Clearing stream quiescent state for all ust apps (in ust_app_clear_quiescent_session() at ust-app.c:4734)
DEBUG1 - 12:54:41.820044 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:41.820073 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.820081 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.827601 [31312/31321]: UST registration received with pid:31341 ppid:24820 uid:0 gid:0 sock:32 name:app-ust (version 7.1) (in thread_registration_apps() at main.c:2267)
DEBUG1 - 12:54:41.827645 [31312/31321]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.827654 [31312/31321]: Accepting application registration (in thread_registration_apps() at main.c:2151)
DEBUG1 - 12:54:41.827666 [31312/31320]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.827690 [31312/31320]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.827699 [31312/31320]: Dispatching UST registration pid:31341 ppid:24820 uid:0 gid:0 sock:32 name:app-ust (version 7.1) (in thread_dispatch_ust_registration() at main.c:1908)
DEBUG3 - 12:54:41.827726 [31312/31320]: UST app creating application for socket 32 (in ust_app_create() at ust-app.c:3295)
DEBUG1 - 12:54:41.827724 [31312/31321]: UST registration received with pid:31341 ppid:24820 uid:0 gid:0 sock:37 name:app-ust (version 7.1) (in thread_registration_apps() at main.c:2267)
DEBUG3 - 12:54:41.827750 [31312/31320]: Created hashtable size 4 at 0x7fab00000a40 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.827755 [31312/31321]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.827763 [31312/31321]: Accepting application registration (in thread_registration_apps() at main.c:2151)
DEBUG3 - 12:54:41.827764 [31312/31320]: Created hashtable size 4 at 0x7fab00000e80 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.827773 [31312/31320]: Created hashtable size 4 at 0x7fab000012c0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.827793 [31312/31320]: Dispatching UST registration pid:31341 ppid:24820 uid:0 gid:0 sock:37 name:app-ust (version 7.1) (in thread_dispatch_ust_registration() at main.c:1908)
DEBUG3 - 12:54:41.827801 [31312/31320]: UST app notify socket 37 is set (in thread_dispatch_ust_registration() at main.c:1965)
DEBUG1 - 12:54:41.827813 [31312/31320]: App registered with pid:31341 ppid:24820 uid:0 gid:0 sock:32 name:app-ust notify_sock:37 (version 7.1) (in ust_app_add() at ust-app.c:3384)
libust[31312/31320]: received tracer version (in ustctl_tracer_version() at ustctl.c:523)
DEBUG2 - 12:54:41.828013 [31312/31320]: UST app global update for app sock 32 for session id 0 (in ust_app_global_update() at ust-app.c:5056)
DEBUG2 - 12:54:41.828026 [31312/31320]: UST app pid: 31341 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2164)
DEBUG3 - 12:54:41.828048 [31312/31320]: Created hashtable size 4 at 0x7fab00004810 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.828072 [31312/31320]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1862)
DEBUG2 - 12:54:41.828088 [31312/31320]: Channel channel0 not found on shadow session copy, creating it (in shadow_copy_session() at ust-app.c:1947)
DEBUG3 - 12:54:41.828099 [31312/31320]: Created hashtable size 4 at 0x7fab00004e90 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828115 [31312/31320]: Created hashtable size 4 at 0x7fab000052d0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828121 [31312/31320]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1044)
DEBUG2 - 12:54:41.828127 [31312/31320]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1787)
DEBUG2 - 12:54:41.828133 [31312/31320]: UST event tp:tptest not found on shadow copy channel (in shadow_copy_channel() at ust-app.c:1828)
DEBUG3 - 12:54:41.828139 [31312/31320]: UST app event tp:tptest allocated (in alloc_ust_app_event() at ust-app.c:1100)
DEBUG3 - 12:54:41.828147 [31312/31320]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1838)
DEBUG3 - 12:54:41.828154 [31312/31320]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.828174 [31312/31320]: Created hashtable size 4 at 0x7fab00007b20 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828180 [31312/31320]: Buffer registry per UID created id: 0, ABI: 64, uid: 0, domain: 2 (in buffer_reg_uid_create() at buffer-registry.c:152)
DEBUG3 - 12:54:41.828203 [31312/31320]: Created hashtable size 4 at 0x7fab0000b030 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828210 [31312/31320]: Created hashtable size 4 at 0x7fab0000b470 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828256 [31312/31320]: Append to metadata: "/* CTF 1.8 */
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828279 [31312/31320]: Append to metadata: "typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
typealias integer { size = 27; align = 1; signed = false; } := uint27_t;
trace {
major = 1;
minor = 8;
uuid = "002be8c6-8430-436b-b30e-777f39fb530b";
byte_order = le;
packet.header := struct {
uint32_t magic;
uint8_t uuid[16];
uint32_t stream_id;
uint64_t stream_instance_id;
};
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828290 [31312/31320]: Append to metadata: "env {
hostname = "ci-node-standalone-amd64-02";
domain = "ust";
tracer_name = "lttng-ust";
tracer_major = 2;
tracer_minor = 9;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828296 [31312/31320]: Append to metadata: "};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828302 [31312/31320]: Append to metadata: "clock {
name = "monotonic";
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828329 [31312/31320]: Append to metadata: " uuid = "127e7c0f-63fd-4aa9-897c-20c67bbb6669";
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828343 [31312/31320]: Append to metadata: " description = "Monotonic Clock";
freq = 1000000000; /* Frequency, in Hz */
/* clock value offset from Epoch is: offset * (1/freq) */
offset = 1513359486047831535;
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828353 [31312/31320]: Append to metadata: "typealias integer {
size = 27; align = 1; signed = false;
map = clock.monotonic.value;
} := uint27_clock_monotonic_t;
typealias integer {
size = 32; align = 8; signed = false;
map = clock.monotonic.value;
} := uint32_clock_monotonic_t;
typealias integer {
size = 64; align = 8; signed = false;
map = clock.monotonic.value;
} := uint64_clock_monotonic_t;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828360 [31312/31320]: Append to metadata: "struct packet_context {
uint64_clock_monotonic_t timestamp_begin;
uint64_clock_monotonic_t timestamp_end;
uint64_t content_size;
uint64_t packet_size;
uint64_t packet_seq_num;
unsigned long events_discarded;
uint32_t cpu_id;
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828380 [31312/31320]: Append to metadata: "struct event_header_compact {
enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
variant <id> {
struct {
uint27_clock_monotonic_t timestamp;
} compact;
struct {
uint32_t id;
uint64_clock_monotonic_t timestamp;
} extended;
} v;
} align(8);
struct event_header_large {
enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
variant <id> {
struct {
uint32_clock_monotonic_t timestamp;
} compact;
struct {
uint32_t id;
uint64_clock_monotonic_t timestamp;
} extended;
} v;
} align(8);
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828388 [31312/31320]: Buffer registry per UID adding to global registry with id: 0 (in buffer_reg_uid_add() at buffer-registry.c:174)
DEBUG3 - 12:54:41.828396 [31312/31320]: UST app buffer registry per UID created successfully (in setup_buffer_reg_uid() at ust-app.c:2127)
DEBUG3 - 12:54:41.828439 [31312/31323]: [ust-thread] Manage notify return from poll on 2 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.828455 [31312/31323]: UST thread notify added sock 37 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
DEBUG3 - 12:54:41.828461 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
libust[31312/31320]: received session handle 1 (in ustctl_create_session() at ustctl.c:178)
DEBUG2 - 12:54:41.828760 [31312/31320]: UST app session created successfully with handle 1 (in create_ust_app_session() at ust-app.c:2239)
DEBUG1 - 12:54:41.828771 [31312/31320]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2855)
DEBUG3 - 12:54:41.828776 [31312/31320]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG2 - 12:54:41.828784 [31312/31320]: UST app creating buffer registry channel for channel0 (in create_buffer_reg_channel() at ust-app.c:2700)
DEBUG3 - 12:54:41.828789 [31312/31320]: Buffer registry channel create with key: 0 (in buffer_reg_channel_create() at buffer-registry.c:380)
DEBUG3 - 12:54:41.828800 [31312/31320]: Created hashtable size 4 at 0x7fab0000b9d0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.828811 [31312/31320]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:120)
DEBUG3 - 12:54:41.828833 [31312/31320]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:784)
DEBUG1 - 12:54:41.828868 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.828907 [31329/31338]: Allocated channel (key 1) (in consumer_allocate_channel() at consumer.c:1025)
DEBUG1 - 12:54:41.829894 [31329/31338]: UST consumer add stream channel0_0 (key: 32) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 12:54:41.829909 [31329/31338]: UST consumer add stream channel0_1 (key: 34) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 12:54:41.829948 [31329/31338]: UST consumer channel added (key: 1) (in add_channel() at ust-consumer.c:115)
DEBUG1 - 12:54:41.829963 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG2 - 12:54:41.829984 [31312/31320]: UST ask channel 1 successfully done with 2 stream(s) (in ask_channel_creation() at ust-consumer.c:215)
DEBUG1 - 12:54:41.830002 [31329/31335]: Channel poll return from wait with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:41.830031 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:41.830016 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.830050 [31329/31335]: Adding channel 29 to poll set (in consumer_thread_channel_poll() at consumer.c:2898)
DEBUG1 - 12:54:41.830073 [31329/31338]: UST consumer sending channel channel0 to sessiond (in send_sessiond_channel() at ust-consumer.c:562)
DEBUG1 - 12:54:41.830094 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:41.830106 [31329/31338]: Relayd adding stream for channel name channel0_0 (in relayd_add_stream() at relayd.c:252)
DEBUG1 - 12:54:41.830508 [31329/31338]: Relayd stream added successfully with handle 1 (in relayd_add_stream() at relayd.c:317)
DEBUG1 - 12:54:41.830519 [31329/31338]: Stream channel0_0 with key 32 sent to relayd id 2 (in consumer_send_relayd_stream() at consumer.c:812)
DEBUG1 - 12:54:41.830529 [31329/31338]: Relayd adding stream for channel name channel0_1 (in relayd_add_stream() at relayd.c:252)
DEBUG1 - 12:54:41.830688 [31329/31338]: Relayd stream added successfully with handle 2 (in relayd_add_stream() at relayd.c:317)
DEBUG1 - 12:54:41.830698 [31329/31338]: Stream channel0_1 with key 34 sent to relayd id 2 (in consumer_send_relayd_stream() at consumer.c:812)
DEBUG1 - 12:54:41.830719 [31329/31338]: UST consumer sending stream 32 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
DEBUG1 - 12:54:41.830730 [31329/31338]: UST consumer sending stream 34 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
DEBUG1 - 12:54:41.830740 [31329/31338]: UST consumer NULL stream sent to sessiond (in send_sessiond_channel() at ust-consumer.c:626)
DEBUG1 - 12:54:41.830843 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.830854 [31329/31337]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:41.830879 [31329/31337]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2555)
DEBUG2 - 12:54:41.830886 [31312/31320]: UST app stream 1 received successfully (in ust_consumer_get_channel() at ust-consumer.c:330)
DEBUG1 - 12:54:41.830892 [31329/31337]: Updating poll fd array (in update_poll_array() at consumer.c:1085)
DEBUG1 - 12:54:41.830907 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG2 - 12:54:41.830909 [31312/31320]: UST app stream 2 received successfully (in ust_consumer_get_channel() at ust-consumer.c:330)
DEBUG1 - 12:54:41.830914 [31329/31337]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:41.830920 [31329/31337]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2555)
DEBUG3 - 12:54:41.830922 [31312/31320]: UST app consumer has no more stream available (in ust_consumer_get_channel() at ust-consumer.c:313)
DEBUG1 - 12:54:41.830926 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG2 - 12:54:41.830932 [31312/31320]: UST app setup buffer registry channel for channel0 (in setup_buffer_reg_channel() at ust-app.c:2750)
DEBUG2 - 12:54:41.830939 [31312/31320]: UST app setup buffer registry stream (in setup_buffer_reg_streams() at ust-app.c:2655)
DEBUG3 - 12:54:41.830945 [31312/31320]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
DEBUG3 - 12:54:41.830952 [31312/31320]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
DEBUG1 - 12:54:41.830957 [31312/31320]: UST app sending buffer registry channel to ust sock 32 (in send_channel_uid_to_ust() at ust-app.c:2786)
DEBUG2 - 12:54:41.830965 [31312/31320]: UST app send channel to sock 32 pid 31341 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:436)
DEBUG2 - 12:54:41.831137 [31312/31320]: UST consumer send stream to app 32 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:399)
DEBUG2 - 12:54:41.831214 [31312/31320]: UST consumer send stream to app 32 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:399)
libust[31312/31320]: received event handle 3 (in ustctl_create_event() at ustctl.c:212)
DEBUG2 - 12:54:41.831333 [31312/31320]: UST app event tp:tptest created successfully for pid:31341 (in create_ust_event() at ust-app.c:1687)
libust[31312/31320]: enabled handle 3 (in ustctl_enable() at ustctl.c:381)
DEBUG2 - 12:54:41.831428 [31312/31320]: UST app event tp:tptest enabled successfully for app (pid: 31341) (in enable_ust_event() at ust-app.c:1591)
DEBUG1 - 12:54:41.831437 [31312/31320]: Starting tracing for ust app pid 31341 (in ust_app_start_trace() at ust-app.c:4322)
DEBUG3 - 12:54:41.831444 [31312/31320]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.831458 [31312/31320]: Created hashtable size 4 at 0x7fab0000df00 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.831465 [31312/31320]: Created hashtable size 4 at 0x7fab0000e2e0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.831470 [31312/31320]: UST app channel metadata allocated (in alloc_ust_app_channel() at ust-app.c:1044)
DEBUG2 - 12:54:41.831478 [31312/31320]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:120)
DEBUG1 - 12:54:41.831510 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.831542 [31329/31338]: Allocated channel (key 2) (in consumer_allocate_channel() at consumer.c:1025)
DEBUG1 - 12:54:41.831645 [31329/31338]: UST consumer add stream metadata (key: 40) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 12:54:41.831657 [31329/31338]: Allocated metadata cache of 4096 bytes (in consumer_metadata_cache_allocate() at consumer-metadata-cache.c:198)
DEBUG1 - 12:54:41.831668 [31329/31338]: UST consumer channel added (key: 2) (in add_channel() at ust-consumer.c:115)
DEBUG1 - 12:54:41.831677 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG2 - 12:54:41.831694 [31312/31320]: UST ask channel 2 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:215)
DEBUG2 - 12:54:41.831706 [31312/31320]: Consumer setup metadata channel key 2 (in consumer_setup_metadata() at consumer.c:1273)
DEBUG1 - 12:54:41.831727 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.831742 [31329/31338]: UST consumer setup metadata key 2 (in setup_metadata() at ust-consumer.c:876)
DEBUG1 - 12:54:41.831752 [31329/31338]: Relayd adding stream for channel name metadata (in relayd_add_stream() at relayd.c:252)
DEBUG1 - 12:54:41.831990 [31329/31338]: Relayd stream added successfully with handle 3 (in relayd_add_stream() at relayd.c:317)
DEBUG1 - 12:54:41.832002 [31329/31338]: Stream metadata with key 40 sent to relayd id 2 (in consumer_send_relayd_stream() at consumer.c:812)
DEBUG1 - 12:54:41.832010 [31329/31338]: Relayd sending streams sent. (in relayd_streams_sent() at relayd.c:336)
DEBUG1 - 12:54:41.832072 [31329/31338]: Relayd streams sent success (in relayd_streams_sent() at relayd.c:369)
DEBUG1 - 12:54:41.832081 [31329/31338]: All streams sent relayd id 2 (in consumer_send_relayd_streams_sent() at consumer.c:850)
DEBUG1 - 12:54:41.832105 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.832117 [31329/31336]: Metadata poll return from wait with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:41.832123 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:41.832131 [31329/31336]: Adding metadata stream 40 to poll set (in consumer_thread_metadata_poll() at consumer.c:2326)
DEBUG1 - 12:54:41.832139 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG2 - 12:54:41.832152 [31312/31320]: UST metadata with key 2 created for app pid 31341 (in create_ust_app_metadata() at ust-app.c:3246)
DEBUG3 - 12:54:41.832164 [31312/31320]: UST app deleting channel metadata (in delete_ust_app_channel() at ust-app.c:457)
DEBUG3 - 12:54:41.832339 [31312/31323]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.832362 [31312/31323]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5629)
DEBUG2 - 12:54:41.832371 [31312/31323]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5683)
DEBUG3 - 12:54:41.832394 [31312/31323]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.832403 [31312/31323]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:784)
DEBUG3 - 12:54:41.832414 [31312/31323]: Append to metadata: "stream {
id = 0;
event.header := struct event_header_compact;
packet.context := struct packet_context;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.832421 [31312/31323]: Append to metadata: "};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.832426 [31312/31323]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5409)
DEBUG3 - 12:54:41.832444 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
libust[31312/31320]: enabled handle 1 (in ustctl_enable() at ustctl.c:381)
libust[31312/31320]: waited for quiescent state (in ustctl_wait_quiescent() at ustctl.c:539)
DEBUG2 - 12:54:41.832628 [31312/31320]: UST trace started for app pid 31341 (in ust_app_global_create() at ust-app.c:5018)
libust[31312/31320]: Sending register done command to 32 (in ustctl_register_done() at ustctl.c:151)
DEBUG3 - 12:54:41.834141 [31312/31323]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.834158 [31312/31323]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5629)
DEBUG2 - 12:54:41.834167 [31312/31323]: UST app ustctl register event received (in ust_app_recv_notify() at ust-app.c:5649)
DEBUG3 - 12:54:41.834201 [31312/31323]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.834211 [31312/31323]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:784)
DEBUG3 - 12:54:41.834219 [31312/31323]: UST registry creating event with event: tp:tptest, sig: int, anint, int, netint, long *, values, char *, text, size_t, textlen, double, doublearg, float, floatarg, id: 0, chan_objd: 2, sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:424)
DEBUG3 - 12:54:41.834232 [31312/31323]: Append to metadata: "event {
name = "tp:tptest";
id = 0;
stream_id = 0;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834240 [31312/31323]: Append to metadata: " loglevel = 13;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834245 [31312/31323]: Append to metadata: " fields := struct {
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834250 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834256 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834263 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _intfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834268 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834273 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834279 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 16; } _intfield2;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834284 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834289 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834294 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 1; encoding = none; base = 10; } _longfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834312 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834317 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834325 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; byte_order = be; } _netintfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834330 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834335 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834341 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 16; byte_order = be; } _netintfieldhex;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834346 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834351 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834357 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 1; encoding = none; base = 10; } _arrfield1[3];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834362 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834367 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834373 [31312/31323]: Append to metadata: "integer { size = 8; align = 8; signed = 1; encoding = UTF8; base = 10; } _arrfield2[10];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834379 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834383 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834390 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 0; encoding = none; base = 10; } __seqfield1_length;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834395 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834400 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834407 [31312/31323]: Append to metadata: "integer { size = 8; align = 8; signed = 1; encoding = none; base = 10; } _seqfield1[ __seqfield1_length ];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834412 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834417 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834423 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 0; encoding = none; base = 10; } __seqfield2_length;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834428 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834432 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834439 [31312/31323]: Append to metadata: "integer { size = 8; align = 8; signed = 1; encoding = UTF8; base = 10; } _seqfield2[ __seqfield2_length ];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834444 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834449 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834454 [31312/31323]: Append to metadata: "string _stringfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834459 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834469 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834475 [31312/31323]: Append to metadata: "floating_point { exp_dig = 8; mant_dig = 24; align = 8; } _floatfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834481 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834486 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834491 [31312/31323]: Append to metadata: "floating_point { exp_dig = 11; mant_dig = 53; align = 8; } _doublefield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834497 [31312/31323]: Append to metadata: " };
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834505 [31312/31323]: UST registry event tp:tptest with id 0 added successfully (in add_event_ust_registry() at ust-app.c:5523)
DEBUG3 - 12:54:41.834511 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG1 - 12:54:41.835295 [31312/31320]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1896)
DEBUG1 - 12:54:41.835309 [31312/31320]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.835315 [31312/31320]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.835320 [31312/31320]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1896)
DEBUG1 - 12:54:41.835322 [31312/31322]: Apps thread return from poll on 2 fds (in thread_manage_apps() at main.c:1592)
DEBUG1 - 12:54:41.835350 [31312/31322]: Apps with sock 32 added to poll set (in thread_manage_apps() at main.c:1649)
DEBUG1 - 12:54:41.835357 [31312/31322]: Apps thread polling (in thread_manage_apps() at main.c:1585)
DEBUG3 - 12:54:41.835716 [31312/31323]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.835731 [31312/31323]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5629)
DEBUG3 - 12:54:41.835740 [31312/31323]: UST app recv notify failed. Application died (in ust_app_recv_notify() at ust-app.c:5636)
DEBUG1 - 12:54:41.835748 [31312/31323]: UST app notify socket unregister 37 (in ust_app_notify_sock_unregister() at ust-app.c:5786)
DEBUG3 - 12:54:41.835762 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG1 - 12:54:41.835803 [31312/31322]: Apps thread return from poll on 3 fds (in thread_manage_apps() at main.c:1592)
DEBUG1 - 12:54:41.835829 [31312/31322]: PID 31341 unregistering with sock 32 (in ust_app_unregister() at ust-app.c:3438)
DEBUG3 - 12:54:41.835865 [31312/31322]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG2 - 12:54:41.835885 [31312/31322]: Consumer push metadata to consumer socket 35 (in consumer_push_metadata() at consumer.c:1308)
DEBUG1 - 12:54:41.835935 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.835972 [31329/31338]: UST consumer push metadata key 2 of len 3724 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1638)
DEBUG3 - 12:54:41.839134 [31312/31322]: Consumer pushing metadata on sock 35 of len 3724 (in consumer_push_metadata() at consumer.c:1326)
DEBUG1 - 12:54:41.839228 [31329/31338]: UST consumer push metadata key 2 of len 3724 (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1237)
DEBUG1 - 12:54:41.839271 [31329/31338]: Writing 3724 bytes from offset 0 in metadata cache (in consumer_metadata_cache_write() at consumer-metadata-cache.c:134)
DEBUG1 - 12:54:41.839291 [31329/31338]: Waiting for metadata to be flushed (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1278)
DEBUG1 - 12:54:41.839307 [31329/31336]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:41.839324 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:41.839332 [31329/31336]: Metadata available on fd 40 (in consumer_thread_metadata_poll() at consumer.c:2364)
DEBUG1 - 12:54:41.839338 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:41.839372 [31329/31336]: Relayd sending metadata of size 3773 (in relayd_send_metadata() at relayd.c:459)
DEBUG1 - 12:54:41.839419 [31329/31336]: Metadata stream id 3 with padding 335 written before data (in write_relayd_metadata_id() at consumer.c:1484)
DEBUG1 - 12:54:41.839431 [31329/31336]: Consumer mmap write() ret 3761 (len 3761) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:41.839441 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:41.839449 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG1 - 12:54:41.844886 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.844930 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.844965 [31312/31319]: Processing client command 17 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.844975 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:41.844982 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:41.844990 [31312/31319]: Stopping all UST traces (in ust_app_stop_trace_all() at ust-app.c:4894)
DEBUG1 - 12:54:41.844997 [31312/31319]: Stopping tracing for ust app pid 31341 (in ust_app_stop_trace() at ust-app.c:4432)
DEBUG1 - 12:54:41.845005 [31312/31319]: Flushing session buffers for all ust apps (in ust_app_flush_session() at ust-app.c:4589)
DEBUG2 - 12:54:41.845013 [31312/31319]: Consumer flush channel key 1 (in consumer_flush_channel() at consumer.c:1174)
DEBUG1 - 12:54:42.394608 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.395640 [31312/31322]: Apps thread polling (in thread_manage_apps() at main.c:1585)
DEBUG1 - 12:54:42.395941 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.396221 [31329/31338]: UST consumer flush channel key 1 (in flush_channel() at ust-consumer.c:751)
DEBUG1 - 12:54:42.396719 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.396794 [31329/31337]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.396974 [31329/31337]: Normal read on fd 32 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG3 - 12:54:42.396971 [31312/31319]: No metadata to push for metadata key 2 (in ust_app_push_metadata() at ust-app.c:575)
DEBUG1 - 12:54:42.397051 [31329/31337]: In UST read_subbuffer (wait_fd: 32, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.397178 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.397447 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.397525 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.397877 [31329/31337]: Consumer mmap write() ret 84 (len 84) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:42.398155 [31329/31337]: Sending metadata request to sessiond, session id 0, per-pid 1, app UID 0 and channek key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2824)
DEBUG1 - 12:54:42.398988 [31312/31330]: Metadata request received for session 0, key 2 (in ust_consumer_metadata_request() at ust-consumer.c:484)
DEBUG3 - 12:54:42.399327 [31312/31330]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:42.399480 [31312/31330]: No metadata to push for metadata key 2 (in ust_app_push_metadata() at ust-app.c:575)
DEBUG1 - 12:54:42.399566 [31312/31330]: No metadata to push (in ust_app_push_metadata() at ust-app.c:578)
DEBUG2 - 12:54:42.399617 [31312/31330]: Consumer push metadata to consumer socket 36 (in consumer_push_metadata() at consumer.c:1308)
DEBUG1 - 12:54:42.399916 [31329/31337]: No new metadata to receive for key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2874)
DEBUG1 - 12:54:42.400081 [31329/31337]: Relayd sending index for stream ID 1 (in relayd_send_index() at relayd.c:839)
DEBUG1 - 12:54:42.400442 [31312/31330]: UST Consumer metadata pushed successfully (in ust_consumer_metadata_request() at ust-consumer.c:523)
DEBUG1 - 12:54:42.402810 [31329/31337]: Normal read on fd 34 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG1 - 12:54:42.402956 [31329/31337]: In UST read_subbuffer (wait_fd: 34, name: channel0_1) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.403620 [31329/31337]: Consumer mmap write() ret 10393 (len 10393) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:42.403755 [31329/31337]: Sending metadata request to sessiond, session id 0, per-pid 1, app UID 0 and channek key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2824)
DEBUG1 - 12:54:42.404015 [31312/31330]: Metadata request received for session 0, key 2 (in ust_consumer_metadata_request() at ust-consumer.c:484)
DEBUG3 - 12:54:42.404118 [31312/31330]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:42.404191 [31312/31330]: No metadata to push for metadata key 2 (in ust_app_push_metadata() at ust-app.c:575)
DEBUG1 - 12:54:42.404236 [31312/31330]: No metadata to push (in ust_app_push_metadata() at ust-app.c:578)
DEBUG2 - 12:54:42.404279 [31312/31330]: Consumer push metadata to consumer socket 36 (in consumer_push_metadata() at consumer.c:1308)
DEBUG1 - 12:54:42.404499 [31329/31337]: No new metadata to receive for key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2874)
DEBUG1 - 12:54:42.404627 [31329/31337]: Relayd sending index for stream ID 2 (in relayd_send_index() at relayd.c:839)
DEBUG1 - 12:54:42.404915 [31312/31330]: UST Consumer metadata pushed successfully (in ust_consumer_metadata_request() at ust-consumer.c:523)
DEBUG1 - 12:54:42.407127 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:42.416927 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.417230 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.417627 [31312/31319]: Processing client command 24 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.417721 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.417780 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.417855 [31312/31319]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1118)
DEBUG1 - 12:54:42.418180 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.418383 [31329/31338]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1381)
DEBUG1 - 12:54:42.418453 [31329/31338]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3601)
DEBUG1 - 12:54:42.418532 [31329/31338]: Relayd begin data pending (in relayd_begin_data_pending() at relayd.c:738)
DEBUG1 - 12:54:42.419914 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.420024 [31329/31338]: Relayd data pending for stream id 1 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.420955 [31329/31338]: Relayd data is NOT pending for stream id 1 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.421068 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.421127 [31329/31338]: Relayd data pending for stream id 2 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.421821 [31329/31338]: Relayd data is NOT pending for stream id 2 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.421916 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.421966 [31329/31338]: UST consumer metadata pending check: contiguous 3724 vs pushed 3724 (in lttng_ustconsumer_data_pending() at ust-consumer.c:2664)
DEBUG1 - 12:54:42.422024 [31329/31338]: Relayd checking quiescent control state (in relayd_quiescent_control() at relayd.c:693)
DEBUG1 - 12:54:42.422830 [31329/31338]: Relayd end data pending (in relayd_end_data_pending() at relayd.c:786)
DEBUG1 - 12:54:42.423723 [31329/31338]: Relayd end data pending is data inflight: 0 (in relayd_end_data_pending() at relayd.c:811)
DEBUG1 - 12:54:42.423872 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.424032 [31312/31319]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1154)
DEBUG1 - 12:54:42.424177 [31312/31319]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.424344 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.424412 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.424924 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.425127 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.425419 [31312/31319]: Processing client command 11 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.425506 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.425562 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.425628 [31312/31319]: Listing domains found UST global domain (in cmd_list_domains() at cmd.c:2851)
DEBUG1 - 12:54:42.425743 [31312/31319]: Sending response (size: 328, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.425866 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.425923 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.426404 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.426578 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.426840 [31312/31319]: Processing client command 10 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.426918 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.426971 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.427059 [31312/31319]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 12:54:42.427125 [31312/31319]: Setting relayd for session trace (in cmd_setup_relayd() at cmd.c:1014)
DEBUG3 - 12:54:42.427213 [31312/31319]: Number of UST global channels 1 (in cmd_list_channels() at cmd.c:2934)
DEBUG1 - 12:54:42.427280 [31312/31319]: Listing channels for session trace (in list_lttng_channels() at cmd.c:245)
DEBUG3 - 12:54:42.427373 [31312/31319]: Consumer discarded events id 0 (in consumer_get_discarded_events() at consumer.c:1428)
DEBUG1 - 12:54:42.427683 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.427873 [31329/31338]: UST consumer discarded events command for session id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1747)
DEBUG1 - 12:54:42.427969 [31329/31338]: UST consumer discarded events command for session id 0, channel key 1 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1774)
DEBUG1 - 12:54:42.428049 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.428177 [31312/31319]: Consumer discarded 0 events in session id 0 (in consumer_get_discarded_events() at consumer.c:1465)
DEBUG1 - 12:54:42.428348 [31312/31319]: Sending response (size: 660, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.428483 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.428540 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.521311 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.521686 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.522088 [31312/31319]: Processing client command 13 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.522192 [31312/31319]: Counting number of available session for UID 0 GID 0 (in lttng_sessions_count() at main.c:2954)
DEBUG1 - 12:54:42.522332 [31312/31319]: Getting all available session for UID 0 GID 0 (in cmd_list_lttng_sessions() at cmd.c:3049)
DEBUG1 - 12:54:42.522518 [31312/31319]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.522724 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.522790 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.523330 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.523534 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.523811 [31312/31319]: Processing client command 17 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.523906 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.523964 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:42.524038 [31312/31319]: Sending response (size: 20, retcode: Tracing has already been stopped (81)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.524158 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.524218 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.524563 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.524712 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.524969 [31312/31319]: Processing client command 24 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.525049 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.525104 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.525169 [31312/31319]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1118)
DEBUG1 - 12:54:42.525414 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.525849 [31329/31338]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1381)
DEBUG1 - 12:54:42.525944 [31329/31338]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3601)
DEBUG1 - 12:54:42.526028 [31329/31338]: Relayd begin data pending (in relayd_begin_data_pending() at relayd.c:738)
DEBUG1 - 12:54:42.527667 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.527787 [31329/31338]: Relayd data pending for stream id 1 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.528588 [31329/31338]: Relayd data is NOT pending for stream id 1 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.528697 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.528875 [31329/31338]: Relayd data pending for stream id 2 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.529536 [31329/31338]: Relayd data is NOT pending for stream id 2 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.529627 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.529674 [31329/31338]: UST consumer metadata pending check: contiguous 3724 vs pushed 3724 (in lttng_ustconsumer_data_pending() at ust-consumer.c:2664)
DEBUG1 - 12:54:42.529727 [31329/31338]: Relayd checking quiescent control state (in relayd_quiescent_control() at relayd.c:693)
DEBUG1 - 12:54:42.530416 [31329/31338]: Relayd end data pending (in relayd_end_data_pending() at relayd.c:786)
DEBUG1 - 12:54:42.531372 [31329/31338]: Relayd end data pending is data inflight: 0 (in relayd_end_data_pending() at relayd.c:811)
DEBUG1 - 12:54:42.531518 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.531665 [31312/31319]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1154)
DEBUG1 - 12:54:42.531801 [31312/31319]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.531945 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.532003 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.532446 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.532636 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.532915 [31312/31319]: Processing client command 17 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.533000 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.533054 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:42.533121 [31312/31319]: Sending response (size: 20, retcode: Tracing has already been stopped (81)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.533230 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.533285 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.533594 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.533741 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.533974 [31312/31319]: Processing client command 9 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.534054 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.534105 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.534170 [31312/31319]: No kernel session when tearing down session (in kernel_destroy_session() at kernel.c:897)
DEBUG2 - 12:54:42.534246 [31312/31319]: Sending destroy relayd command to consumer sock 35 (in consumer_send_destroy_relayd() at consumer.c:208)
DEBUG1 - 12:54:42.534438 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.534609 [31329/31338]: UST consumer destroying relayd 2 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1346)
DEBUG1 - 12:54:42.534790 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG2 - 12:54:42.534911 [31312/31319]: Consumer send destroy relayd command done (in consumer_send_destroy_relayd() at consumer.c:223)
DEBUG1 - 12:54:42.535004 [31312/31319]: Destroy all UST traces (in ust_app_destroy_trace_all() at ust-app.c:4922)
DEBUG2 - 12:54:42.535069 [31312/31319]: Trace UST destroy session 0 (in trace_ust_destroy_session() at trace-ust.c:1159)
DEBUG3 - 12:54:42.535476 [31312/31319]: Buffer registry per UID destroy with id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_destroy() at buffer-registry.c:678)
DEBUG2 - 12:54:42.535577 [31312/31319]: Consumer close metadata channel key 2 (in consumer_close_metadata() at consumer.c:1240)
DEBUG1 - 12:54:42.535810 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.535986 [31329/31338]: UST consumer close metadata key 2 (in close_metadata() at ust-consumer.c:835)
DEBUG3 - 12:54:42.535941 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.536069 [31329/31338]: Closing metadata channel key 2 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2705)
DEBUG1 - 12:54:42.536320 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.536425 [31329/31336]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:42.536486 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:42.536545 [31329/31336]: Metadata fd 40 is hup|err. (in consumer_thread_metadata_poll() at consumer.c:2386)
DEBUG1 - 12:54:42.536593 [31329/31336]: Attempting to flush and consume the UST buffers (in consumer_thread_metadata_poll() at consumer.c:2390)
DEBUG1 - 12:54:42.536824 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.536932 [31329/31336]: Relayd sending metadata of size 49 (in relayd_send_metadata() at relayd.c:459)
DEBUG1 - 12:54:42.537223 [31329/31336]: Metadata stream id 3 with padding 4059 written before data (in write_relayd_metadata_id() at consumer.c:1484)
DEBUG1 - 12:54:42.537307 [31329/31336]: Consumer mmap write() ret 37 (len 37) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:42.537387 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.537526 [31329/31336]: Closing metadata channel key 2 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2705)
DEBUG1 - 12:54:42.537656 [31329/31336]: Relayd closing stream id 3 (in relayd_send_close_stream() at relayd.c:594)
DEBUG1 - 12:54:42.538253 [31312/31319]: Destroying session trace (in session_destroy() at session.c:331)
DEBUG1 - 12:54:42.538417 [31312/31319]: Empty ltt_sessions_ht_by_id, destroying it (in del_session_ht() at session.c:240)
DEBUG1 - 12:54:42.538553 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.538693 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.538748 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.538896 [31312/31325]: Thread kernel return from poll on 2 fds (in thread_manage_kernel() at main.c:1105)
DEBUG1 - 12:54:42.539163 [31312/31325]: Updating kernel poll set (in update_kernel_poll() at main.c:888)
DEBUG1 - 12:54:42.539230 [31312/31325]: Thread kernel polling (in thread_manage_kernel() at main.c:1098)
DEBUG3 - 12:54:42.637932 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.638202 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.740765 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.741037 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.842380 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.842639 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.921328 [31329/31336]: Relayd close stream id 3 successfully (in relayd_send_close_stream() at relayd.c:623)
DEBUG1 - 12:54:42.921639 [31329/31336]: Consumer delete channel key 2 (in consumer_del_channel() at consumer.c:360)
DEBUG1 - 12:54:42.922532 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG3 - 12:54:42.943929 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.944180 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.104595 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.104621 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.114787 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.114812 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.119931 [31329/31348]: Destroying metadata cache (in consumer_metadata_cache_destroy() at consumer-metadata-cache.c:220)
DEBUG3 - 12:54:42.119951 [31312/31344]: Call RCU deleting app PID 31341 (in delete_ust_app_rcu() at ust-app.c:940)
libringbuffer[31329/31348]: ring buffer relay-metadata-mmap: 0 records written, 0 records overrun
(in lib_ring_buffer_print_errors() at ring_buffer_frontend.c:1647)
DEBUG3 - 12:54:42.119989 [31312/31344]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:42.120016 [31312/31344]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:457)
DEBUG2 - 12:54:42.120061 [31312/31344]: UST app pid 31341 deleted (in delete_ust_app() at ust-app.c:924)
DEBUG2 - 12:54:42.120070 [31312/31344]: Trace destroy UST event tp:tptest (in trace_ust_destroy_event() at trace-ust.c:1003)
DEBUG2 - 12:54:42.120076 [31312/31344]: Trace destroy UST channel channel0 (in _trace_ust_destroy_channel() at trace-ust.c:1068)
DEBUG3 - 12:54:42.120083 [31312/31344]: Buffer registry session destroy (in buffer_reg_session_destroy() at buffer-registry.c:597)
DEBUG3 - 12:54:42.120090 [31312/31344]: Buffer registry channel destroy with key 0 (in buffer_reg_channel_destroy() at buffer-registry.c:552)
DEBUG3 - 12:54:42.120095 [31312/31344]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
DEBUG3 - 12:54:42.120102 [31312/31344]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
DEBUG1 - 12:54:42.120146 [31329/31335]: Channel poll return from wait with 2 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:42.120164 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:42.120173 [31329/31335]: Channel fd 29 is hup|err. (in consumer_thread_channel_poll() at consumer.c:2999)
DEBUG1 - 12:54:42.120199 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:42.120214 [31329/31337]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.120221 [31329/31337]: fd 32 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2657)
DEBUG1 - 12:54:42.120227 [31329/31337]: Polling fd 32 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120232 [31329/31337]: fd 34 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2657)
DEBUG1 - 12:54:42.120247 [31329/31337]: Polling fd 34 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120252 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:42.120259 [31329/31337]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.120264 [31329/31337]: Normal read on fd 32 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG1 - 12:54:42.120269 [31329/31337]: In UST read_subbuffer (wait_fd: 32, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.120276 [31329/31337]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2468)
DEBUG1 - 12:54:42.120282 [31329/31337]: Normal read on fd 34 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG1 - 12:54:42.120287 [31329/31337]: In UST read_subbuffer (wait_fd: 34, name: channel0_1) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.120292 [31329/31337]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2468)
DEBUG1 - 12:54:42.120297 [31329/31337]: Polling fd 32 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120307 [31329/31337]: Consumer stream destroy monitored key: 32 (in destroy_close_stream() at consumer-stream.c:265)
DEBUG1 - 12:54:42.120323 [31329/31337]: Relayd closing stream id 1 (in relayd_send_close_stream() at relayd.c:594)
DEBUG1 - 12:54:42.120530 [31329/31337]: Relayd close stream id 1 successfully (in relayd_send_close_stream() at relayd.c:623)
DEBUG1 - 12:54:42.120555 [31329/31337]: Polling fd 34 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120592 [31329/31337]: Consumer stream destroy monitored key: 34 (in destroy_close_stream() at consumer-stream.c:265)
DEBUG1 - 12:54:42.120611 [31329/31337]: Relayd closing stream id 2 (in relayd_send_close_stream() at relayd.c:594)
DEBUG1 - 12:54:42.120754 [31329/31337]: Relayd close stream id 2 successfully (in relayd_send_close_stream() at relayd.c:623)
DEBUG1 - 12:54:42.120769 [31329/31337]: Consumer destroy and close relayd socket pair (in consumer_destroy_relayd() at consumer.c:338)
DEBUG1 - 12:54:42.120779 [31329/31337]: Consumer delete channel key 1 (in consumer_del_channel() at consumer.c:360)
DEBUG1 - 12:54:42.123937 [31329/31337]: Updating poll fd array (in update_poll_array() at consumer.c:1085)
DEBUG1 - 12:54:42.123949 [31329/31337]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:42.123932 [31329/31334]: Signal timer metadata thread teardown (in consumer_timer_thread() at consumer-timer.c:594)
DEBUG3 - 12:54:42.124982 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.125006 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.135182 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.135209 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.145386 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.145413 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
libringbuffer[31329/31348]: ring buffer relay-discard-mmap, cpu 0: 0 records written, 0 records overrun
(in lib_ring_buffer_print_errors() at ring_buffer_frontend.c:1653)
libringbuffer[31329/31348]: ring buffer relay-discard-mmap, cpu 1: 0 records written, 0 records overrun
(in lib_ring_buffer_print_errors() at ring_buffer_frontend.c:1653)
DEBUG3 - 12:54:42.155595 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.155631 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.165823 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.165848 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.174367 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.174396 [31329/31338]: Consumer received unexpected message size 0 (expects 12668) (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1309)
DEBUG1 - 12:54:42.174404 [31329/31338]: Communication interrupted on command socket (in consumer_thread_sessiond_poll() at consumer.c:3185)
DEBUG1 - 12:54:42.174409 [31329/31338]: Consumer thread sessiond poll exiting (in consumer_thread_sessiond_poll() at consumer.c:3200)
DEBUG1 - 12:54:42.174414 [31329/31338]: UST consumer closing all metadata streams (in lttng_ustconsumer_close_all_metadata() at ust-consumer.c:2748)
DEBUG1 - 12:54:42.174547 [31329/31335]: Channel poll return from wait with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:42.174562 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:42.174574 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:42.174579 [31329/31335]: Channel poll return from wait with 0 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:42.174584 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:42.174617 [31329/31333]: Health check thread dying (in thread_manage_health() at health-consumerd.c:342)
DEBUG1 - 12:54:42.174704 [31329/31337]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.174728 [31329/31337]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2555)
DEBUG1 - 12:54:42.174739 [31329/31337]: Consumer delete flagged data stream (in validate_endpoint_status_data_stream() at consumer.c:2175)
DEBUG1 - 12:54:42.174746 [31329/31337]: polling thread exiting (in consumer_thread_data_poll() at consumer.c:2697)
DEBUG1 - 12:54:42.174772 [31329/31336]: Metadata poll return from wait with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:42.174798 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:42.174804 [31329/31336]: Metadata thread pipe hung up (in consumer_thread_metadata_poll() at consumer.c:2332)
DEBUG1 - 12:54:42.174818 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG1 - 12:54:42.174824 [31329/31336]: Metadata poll return from wait with 0 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:42.174829 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:42.174833 [31329/31336]: Metadata poll thread exiting (in consumer_thread_metadata_poll() at consumer.c:2426)
DEBUG1 - 12:54:42.184797 [31329/31335]: Channel poll thread exiting (in consumer_thread_channel_poll() at consumer.c:3036)
DEBUG1 - 12:54:42.264806 [31329/31329]: Consumer destroying it. Closing everything. (in lttng_consumer_destroy() at consumer.c:1425)
DEBUG1 - 12:54:42.331939 [31329/31329]: Destroying run_as worker (in run_as_destroy_worker() at runas.c:714)
DEBUG1 - 12:54:42.331956 [31329/31329]: Closing run_as worker socket (in run_as_destroy_worker() at runas.c:720)
DEBUG1 - 12:54:42.332015 [31332/31332]: run_as worker exiting (ret = 0) (in run_as_create_worker() at runas.c:664)
libust[31332/31332]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at lttng-ring-buffer-metadata-client.h:356)
DEBUG1 - 12:54:42.332409 [31329/31329]: lttng-runas terminated with status code 0 (in run_as_destroy_worker() at runas.c:742)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at lttng-ring-buffer-metadata-client.h:356)
DEBUG1 - 12:54:42.332830 [31313/31313]: run_as worker exiting (ret = 0) (in run_as_create_worker() at runas.c:664)
libust[31313/31313]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at lttng-ring-buffer-metadata-client.h:356)
</pre></p>
<p>Basic setup:<br /><pre>
0: ['make', 'V=1']
1: ['lttng', 'create', '--set-url=net://localhost:38120:42335', 'trace', '--live']
2: ['lttng', 'enable-event', '-u', 'tp:tptest']
3: ['lttng', 'start']
4: ['./app', '100']
5: ['lttng', 'stop']
6: ['lttng', 'destroy', '-a']
</pre></p>
<p>Current code generating the test case can be found here : <a class="external" href="https://github.com/lttng/lttng-ivc/blob/master/lttng_ivc/tests/babeltrace/live/test_babeltrace_live.py">https://github.com/lttng/lttng-ivc/blob/master/lttng_ivc/tests/babeltrace/live/test_babeltrace_live.py</a></p> Babeltrace - Bug #1121 (New): Babeltrace 2.0-pre reports negative timestamp with ctf-writer traceshttps://bugs.lttng.org/issues/11212017-07-07T23:58:27ZAnonymous
<p>I am trying to read the following two traces with Babeltrace 2:<br /><a class="external" href="https://github.com/tracecompass/tracecompass-test-traces/tree/master/ctf/src/main/resources/ctfwriter_JF8nq3">https://github.com/tracecompass/tracecompass-test-traces/tree/master/ctf/src/main/resources/ctfwriter_JF8nq3</a><br /><a class="external" href="https://github.com/tracecompass/tracecompass-test-traces/tree/master/ctf/src/main/resources/funky_trace">https://github.com/tracecompass/tracecompass-test-traces/tree/master/ctf/src/main/resources/funky_trace</a></p>
<p>The timestamps are reported as negative, like this:</p>
<pre><code>[-8828042786.100214613] (+0.000000001) Spammy_Event: { custom_packet_context_field = 2 }, { common_event_context = 29 }, { field_1 = 28169, a_string = "This is a test" }<br />[warning] Fallback to [sec.ns] to print negative time value. Use --clock-seconds.</code></pre>
<p>The timestamps were reported correctly with Babeltrace 1 on the same traces.</p> Babeltrace - Bug #1096 (New): Babeltrace takes 100% CPU and 100% mem reading a malformed tracehttps://bugs.lttng.org/issues/10962017-04-22T01:17:51ZFrancis Deslauriersfrancis.deslauriers@efficios.com
<p>Babeltrace Version: 1.5.2<br />While hacking on the LTTng kernel tracer, I mistakenly wrote a ctf_sequence with 1 element but a length of 0 resulting in a malformed trace.<br />When reading the malformed trace, Babeltrace hangs and takes 100% of one CPU and 100% of the available memory.</p>
<p>I attached the trace in question.</p>