LTTng bugs repository: Issueshttps://bugs.lttng.org/https://bugs.lttng.org/themes/lttng/favicon/a.ico?14249722912023-10-26T18:56:27ZLTTng bugs repository
Redmine Babeltrace - Bug #1397 (New): reserved identifier violationhttps://bugs.lttng.org/issues/13972023-10-26T18:56:27ZMarkus Elfring
<p>I would like to point out that a few identifiers do eventually not fit to the expected naming convention of the C language standard.<br /><a class="external" href="https://www.securecoding.cert.org/confluence/display/c/DCL37-C.+Do+not+declare+or+define+a+reserved+identifier">https://www.securecoding.cert.org/confluence/display/c/DCL37-C.+Do+not+declare+or+define+a+reserved+identifier</a></p>
<p>Would you like to adjust your selection for unique names?</p>
Examples:
<ul>
<li>__BT_IN_BABELTRACE_H<br /> <a class="external" href="https://github.com/efficios/babeltrace/blob/8a87cdbd41e2e04b1b64e9959751cdabe72281c1/include/babeltrace2/babeltrace.h#L13-L17">https://github.com/efficios/babeltrace/blob/8a87cdbd41e2e04b1b64e9959751cdabe72281c1/include/babeltrace2/babeltrace.h#L13-L17</a></li>
<li>_BABELTRACE_UTC_H<br /> <a class="external" href="https://github.com/efficios/babeltrace/blob/8a87cdbd41e2e04b1b64e9959751cdabe72281c1/src/compat/utc.h#L7-L8">https://github.com/efficios/babeltrace/blob/8a87cdbd41e2e04b1b64e9959751cdabe72281c1/src/compat/utc.h#L7-L8</a></li>
</ul> 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 #1364 (New): CTF: Mismatching variant and tag selector and field names causes a ...https://bugs.lttng.org/issues/13642022-11-25T22:09:40ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>Running <code>200e2a8d2</code>, decoding a CTF trace that has mismatching variant field and enumeration mapping names results in a crash:</p>
<pre>
❯ babeltrace ~/lttng-traces/auto-20221125-164416/ust/uid/1000/64-bit
(╯°□°)╯︵ ┻━┻ ctf-meta-translate.cpp:276: ctf_field_class_variant_to_ir(): Assertion `mapping` failed.
[1] 215518 IOT instruction (core dumped) babeltrace ~/lttng-traces/auto-20221125-164416/ust/uid/1000/64-bit
</pre>
<pre>
#0 0x00007fc99129964c in ?? () from /usr/lib/libc.so.6
#1 0x00007fc991249958 in raise () from /usr/lib/libc.so.6
#2 0x00007fc99123353d in abort () from /usr/lib/libc.so.6
#3 0x00007fc990ec3bf5 in bt_common_abort () at common.c:2111
#4 0x00007fc990f1d298 in bt_common_assert_failed (file=0x7fc990f28fbb "ctf-meta-translate.cpp",
line=276, func=0x7fc990f290e8 "ctf_field_class_variant_to_ir",
assertion=0x7fc990f2913f "mapping") at assert.c:40
#5 0x00007fc990ed1612 in ctf_field_class_variant_to_ir (fc=0x55568bfbf780, ctx=0x7ffd71c5f7f0)
at ctf-meta-translate.cpp:276
#6 ctf_field_class_to_ir (ctx=ctx@entry=0x7ffd71c5f7f0, fc=0x55568bfbf780)
at ctf-meta-translate.cpp:390
#7 0x00007fc990ed1883 in translate_struct_field_class_members (with_header_prefix=<optimized out>,
context_fc=<optimized out>, ir_fc=<optimized out>, fc=<optimized out>, ctx=<optimized out>)
at ctf-meta-translate.cpp:159
#8 ctf_field_class_struct_to_ir (fc=0x55568bf13490, ctx=0x7ffd71c5f7f0)
at ctf-meta-translate.cpp:173
#9 ctf_field_class_to_ir (ctx=ctx@entry=0x7ffd71c5f7f0, fc=0x55568bf13490)
at ctf-meta-translate.cpp:381
#10 0x00007fc990ed2464 in scope_ctf_field_class_to_ir (ctx=0x7ffd71c5f7f0)
at ctf-meta-translate.cpp:453
#11 ctf_stream_class_to_ir (ctx=0x7ffd71c5f7f0) at ctf-meta-translate.cpp:552
#12 ctf_trace_class_translate (self_comp=<optimized out>, ir_tc=<optimized out>, tc=0x55568bf14150)
at ctf-meta-translate.cpp:641
#13 0x00007fc990eec028 in ctf_visitor_generate_ir_visit_node (ctx=0x55568bf3a620,
node=0x55568bf14040) at visitor-generate-ir.cpp:4776
#14 0x00007fc990ed965a in ctf_metadata_decoder_append_content (mdec=0x55568bf0b340,
fp=<optimized out>) at decoder.cpp:326
#15 0x00007fc990f0caaa in ctf_fs_metadata_set_trace_class (self_comp=self_comp@entry=0x55568bf13970,
ctf_fs_trace=ctf_fs_trace@entry=0x55568bf09da0, config=config@entry=0x55568bf0b478)
at metadata.cpp:103
#16 0x00007fc990f098b8 in ctf_fs_trace_create (log_level=BT_LOGGING_LEVEL_WARNING,
metadata_config=0x55568bf0b478, name=0x0,
path=0x55568bf0b4a0 "/home/jgalar/lttng-traces/auto-20221125-164416/ust/uid/1000/64-bit",
self_comp_class=0x0, self_comp=0x55568bf13970) at fs.cpp:1027
#17 ctf_fs_component_create_ctf_fs_trace_one_path (self_comp_class=0x0, self_comp=0x55568bf13970,
traces=0x55568bf35620, trace_name=0x0, path_param=<optimized out>, ctf_fs=0x55568bf0b460)
at fs.cpp:1129
#18 ctf_fs_component_create_ctf_fs_trace (ctf_fs=ctf_fs@entry=0x55568bf0b460,
paths_value=<optimized out>, trace_name_value=<optimized out>,
self_comp=self_comp@entry=0x55568bf13970, self_comp_class=self_comp_class@entry=0x0)
at fs.cpp:2002
#19 0x00007fc990f0c3c3 in ctf_fs_create (self_comp_src=0x55568bf13970, params=0x55568bf0d9a0)
at fs.cpp:2278
#20 ctf_fs_init (self_comp_src=0x55568bf13970, config=config@entry=0x0,
params=params@entry=0x55568bf0d9a0, init_method_data=init_method_data@entry=0x0) at fs.cpp:2311
#21 0x00007fc991568b4d in add_component_with_init_method_data (graph=graph@entry=0x55568bf13800,
comp_cls=comp_cls@entry=0x55568bf32970,
init_method=0x7fc990f0c320 <ctf_fs_init(bt_self_component_source*, bt_self_component_source_configuration*, bt_value const*, void*)>, name=name@entry=0x55568bf0d910 "auto-disc-source-ctf-fs",
params=params@entry=0x55568bf0d9a0, init_method_data=init_method_data@entry=0x0,
log_level=BT_LOGGING_LEVEL_WARNING, user_component=0x7ffd71c5fd00,
api_func=0x7fc9915a9660 <__func__.13> "bt_graph_add_source_component",
init_method_name=0x7fc9915aa860 "bt_component_class_source_initialize_method") at graph.c:1048
#22 0x00007fc99156aaae in add_source_component_with_initialize_method_data (
api_func=0x7fc9915a9660 <__func__.13> "bt_graph_add_source_component", component=0x7ffd71c5fd00,
log_level=BT_LOGGING_LEVEL_WARNING, init_method_data=0x0, params=0x55568bf0d9a0,
name=0x55568bf0d910 "auto-disc-source-ctf-fs", comp_cls=0x55568bf32970, graph=0x55568bf13800)
at graph.c:1127
#23 bt_graph_add_source_component (graph=0x55568bf13800, comp_cls=comp_cls@entry=0x55568bf32970,
name=0x55568bf0d910 "auto-disc-source-ctf-fs", params=0x55568bf0d9a0,
log_level=BT_LOGGING_LEVEL_WARNING, component=component@entry=0x7ffd71c5fd00) at graph.c:1152
#24 0x000055568aa845d6 in cmd_run_ctx_create_components_from_config_components (
ctx=ctx@entry=0x7ffd71c5fde0, cfg_components=<optimized out>) at babeltrace2.c:2259
#25 0x000055568aa7ffe4 in cmd_run_ctx_create_components (ctx=0x7ffd71c5fde0) at babeltrace2.c:2355
#26 cmd_run (cfg=0x55568bf14390) at babeltrace2.c:2469
--Type <RET> for more, q to quit, c to continue without paging--
#27 main (argc=<optimized out>, argv=<optimized out>) at babeltrace2.c:2679
</pre>
<p>The relevant part of the trace's metadata is as-follows where you can see "_none" and "none" don't match.<br /><pre>
event.context := struct {
enum : integer { size = 8; align = 8; signed = true; } {
"none" = 0,
"_int8" = 1,
"_int16" = 2,
"_int32" = 3,
"_int64" = 4,
"_uint8" = 5,
"_uint16" = 6,
"_uint32" = 7,
"_uint64" = 8,
"_float" = 9,
"_double" = 10,
"_string" = 11
} __app_lol_gooo_tag;
variant <__app_lol_gooo_tag> {
struct {} _none;
integer { size = 8; align = 8; signed = true; } _int8;
integer { size = 16; align = 8; signed = true; } _int16;
integer { size = 32; align = 8; signed = true; } _int32;
integer { size = 64; align = 8; signed = true; } _int64;
integer { size = 8; align = 8; } _uint8;
integer { size = 16; align = 8; } _uint16;
integer { size = 32; align = 8; } _uint32;
integer { size = 64; align = 8; } _uint64;
floating_point { align = 8; mant_dig = 24; exp_dig = 8; } _float;
floating_point { align = 8; mant_dig = 53; exp_dig = 11; } _double;
string _string;
} __app_lol_gooo;
};
</pre></p>
<p>Arguably, the CTF 1.8.3 specification says that:<br /><pre>
Each variant type selector possess a field name, which is a unique identifier within the variant. The identifier is not allowed to use any reserved keyword. Replacing reserved keywords with underscore-prefixed field names is recommended. Fields starting with an underscore should have their leading underscore removed by the CTF trace readers.
</pre></p>
<p>As the term "should" is used, this presumably means that the reader could choose to match those or not. I can confirm that Babeltrace 1.5 also fails (but doesn't crash) so it seems reasonable to require an exact match.</p>
<p>I'm joining a trace that reproduces the issue.</p> Babeltrace - Bug #1351 (Feedback): Babeltrace2 failes at a negative clock `offset`https://bugs.lttng.org/issues/13512022-03-21T06:30:01ZHeng Guo
<p>Below lttng packages are using in our project.<br />Lttng_tools: 2.12.3<br />Lttng_ust: 2.12.1<br />Babeltrace: 2.0.3</p>
<p>Get below babletrace2 error when we call "babeltrace2 lts21/live", lts21/live is folder name of trace data.<br /><pre>
01-02 06:43:13.098 1029 1029 E PLUGIN/CTF/META/IR-VISITOR get_unary_unsigned@visitor-generate-ir.c:800 [auto-disc-source-ctf-fs] At line 43 in metadata stream: Invalid constant unsigned integer.
01-02 06:43:13.099 1029 1029 E PLUGIN/CTF/META/IR-VISITOR visit_clock_decl_entry@visitor-generate-ir.c:4356 [auto-disc-source-ctf-fs] At line 43 in metadata stream: Unexpected unary expression for clock class's `offset` attribute.
01-02 06:43:13.099 1029 1029 E PLUGIN/CTF/META/IR-VISITOR visit_clock_decl@visitor-generate-ir.c:4530 [auto-disc-source-ctf-fs] At line 43 in metadata stream: Cannot visit clock class's entry: ret=-22
01-02 06:43:13.099 1029 1029 E PLUGIN/CTF/META/IR-VISITOR ctf_visitor_generate_ir_visit_node@visitor-generate-ir.c:4773 [auto-disc-source-ctf-fs] At line 44 in metadata stream: Cannot visit clock class: ret=-22
01-02 06:43:13.099 1029 1029 E PLUGIN/CTF/META/DECODER ctf_metadata_decoder_append_content@decoder.c:336 [auto-disc-source-ctf-fs] Failed to visit AST node to create CTF IR objects: mdec-addr=0xa245b0, ret=-22
01-02 06:43:13.099 1029 1029 E PLUGIN/SRC.CTF.FS/META ctf_fs_metadata_set_trace_class@metadata.c:128 [auto-disc-source-ctf-fs] Cannot update metadata decoder's content.
01-02 06:43:13.099 1029 1029 E PLUGIN/SRC.CTF.FS ctf_fs_component_create_ctf_fs_trace_one_path@fs.c:1204 [auto-disc-source-ctf-fs] Cannot create trace for `/root/lts21/live/xmu03/session-19700101-000023/ust/uid/0/32-bit`.
01-02 06:43:13.099 1029 1029 W LIB/GRAPH add_component_with_init_method_data@graph.c:973 Component initialization method failed: status=ERROR, comp-addr=0xa1be90, 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", comp-class-is-frozen=0, comp-class-so-handle-addr=0xa278f8, comp-class-so-handle-path="/usr/lib/babeltrace2/plugins/babeltrace-plugin-ctf.so", comp-input-port-count=0, comp-output-port-count=0
01-02 06:43:13.099 1029 1029 E CLI cmd_run_ctx_create_components_from_config_components@babeltrace2.c:2295 Cannot create component: plugin-name="ctf", comp-cls-name="fs", comp-cls-type=1, comp-name="auto-disc-source-ctf-fs"
01-02 06:43:13.099 1029 1029 E CLI cmd_run@babeltrace2.c:2480 Cannot create components.
ERROR: [Babeltrace CLI] (../../../git/src/cli/babeltrace2.c:2480)
Cannot create components.
CAUSED BY [Babeltrace CLI] (../../../git/src/cli/babeltrace2.c:2295)
Cannot create component: plugin-name="ctf", comp-cls-name="fs", comp-cls-type=1, comp-name="auto-disc-source-ctf-fs"
CAUSED BY [libbabeltrace2] (../../../../git/src/lib/graph/graph.c:973)
Component initialization method failed: status=ERROR, comp-addr=0xa1be90, 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", comp-class-is-frozen=0, comp-class-so-handle-addr=0xa278f8, comp-class-so-handle-path="/usr/lib/babeltrace2/plugins/babeltrace-plugin-ctf.so", comp-input-port-count=0, comp-output-port-count=0
CAUSED BY [auto-disc-source-ctf-fs: 'source.ctf.fs'] (../../../../../git/src/plugins/ctf/fs-src/fs.c:1204)
Cannot create trace for `/root/lts21/live/xmu03/session-19700101-000023/ust/uid/0/32-bit`.
</pre></p>
<p>Seems the same issue to <a class="external" href="https://bugs.lttng.org/issues/1277">https://bugs.lttng.org/issues/1277</a>, but there is not fix patch yet.<br />We have the same issue on babeltrace version 1.5.8 too, <a class="external" href="https://bugs.lttng.org/issues/1350">https://bugs.lttng.org/issues/1350</a></p>
<p>We fix it with the attached patch: which is based on latest branch: stable-2.0.<br />Please help check it.</p>
<p>Thanks.</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 #1346 (New): sink.ctf.fs: Assertion failure while encoding length FC of dynamic ...https://bugs.lttng.org/issues/13462022-02-15T16:14:22ZFrancis Deslauriersfrancis.deslauriers@efficios.com
<p>I witnessed this issue while working on the CTF2 support of the sink.ctf.fs component class.</p>
<pre>
(╯°□°)╯︵ ┻━┻ translate-trace-ir-to-ctf-ir.cpp:283: create_relative_field_ref(): Assertion `bt_field_path_item_get_type(fp_item) == BT_FIELD_PATH_ITEM_TYPE_INDEX` failed.
</pre>
<p>The problem is triggered when a length field class of a dynamic array field class is contained within an element of a static array field class. Both dynamic array and its length are in the same element within the static array.</p>
<p>I attached the source of a Python plugin that reproduces this issue.</p>
<p>I can reproduce the issue with the following command:<br /><pre>
babeltrace2 --plugin-path=/home/frdeso/projets/babeltrace-fun-plugins/my-first-components/ -c source.reprod.MyFirstSource -c sink.ctf.fs -p path=\"ici\"
</pre></p>
<p>Here is the full stack trace of the assertion failure:<br /><pre>
#3 0x00007ffff6534c11 in bt_common_assert_failed (file=0x7ffff654c62c "translate-trace-ir-to-ctf-ir.cpp", line=283, func=0x7ffff654cf00 "create_relative_field_ref", assertion=0x7ffff654cf3a "bt_field_path_item_get_type(fp_item) == BT_FIELD_PATH_ITEM_TYPE_INDEX") at assert.c:40
#4 0x00007ffff6505624 in create_relative_field_ref (ctx=0x7fffffffe0f8, tgt_ir_field_path=0x5555555980a0, tgt_field_ref=0x555555599900, user_tgt_fc=0x0) at translate-trace-ir-to-ctf-ir.cpp:283
#5 0x00007ffff650529b in resolve_field_class (ctx=0x7fffffffe0f8, tgt_ir_field_path=0x5555555980a0, tgt_field_ref=0x555555599900, create_before=0x55555559b420, user_tgt_fc=0x0) at translate-trace-ir-to-ctf-ir.cpp:510
#6 0x00007ffff6503ccb in translate_dynamic_array_field_class (ctx=0x7fffffffe0f8) at translate-trace-ir-to-ctf-ir.cpp:1087
#7 0x00007ffff65035b7 in translate_field_class (ctx=0x7fffffffe0f8) at translate-trace-ir-to-ctf-ir.cpp:1191
#8 0x00007ffff6502e5a in translate_structure_field_class_members (ctx=0x7fffffffe0f8, struct_fc=0x55555559b2f0, ir_fc=0x5555556fed80) at translate-trace-ir-to-ctf-ir.cpp:615
#9 0x00007ffff650398a in translate_structure_field_class (ctx=0x7fffffffe0f8) at translate-trace-ir-to-ctf-ir.cpp:638
#10 0x00007ffff6503570 in translate_field_class (ctx=0x7fffffffe0f8) at translate-trace-ir-to-ctf-ir.cpp:1187
#11 0x00007ffff6503b18 in translate_static_array_field_class (ctx=0x7fffffffe0f8) at translate-trace-ir-to-ctf-ir.cpp:1061
#12 0x00007ffff650358f in translate_field_class (ctx=0x7fffffffe0f8) at translate-trace-ir-to-ctf-ir.cpp:1189
#13 0x00007ffff6502e5a in translate_structure_field_class_members (ctx=0x7fffffffe0f8, struct_fc=0x55555559b120, ir_fc=0x5555557500d0) at translate-trace-ir-to-ctf-ir.cpp:615
#14 0x00007ffff6502819 in translate_scope_field_class (ctx=0x7fffffffe0f8, scope=BT_FIELD_PATH_SCOPE_EVENT_PAYLOAD, fc=0x55555559b028, ir_fc=0x5555557500d0) at translate-trace-ir-to-ctf-ir.cpp:1446
#15 0x00007ffff6501ab9 in translate_event_class (fs_sink=0x555555598510, sc=0x55555559ae80, ir_ec=0x5555557166e0, out_ec=0x7fffffffe1e8) at translate-trace-ir-to-ctf-ir.cpp:1503
#16 0x00007ffff6501955 in try_translate_event_class_trace_ir_to_ctf_ir (fs_sink=0x555555598510, sc=0x55555559ae80, ir_ec=0x5555557166e0, out_ec=0x7fffffffe1e8) at translate-trace-ir-to-ctf-ir.cpp:1532
#17 0x00007ffff64fe4a4 in handle_event_msg (fs_sink=0x555555598510, msg=0x55555559a530) at fs-sink.cpp:266
#18 0x00007ffff64fe082 in ctf_fs_sink_consume (self_comp=0x555555598480) at fs-sink.cpp:957
</pre></p> Babeltrace - Bug #1338 (New): Crash when specifying convert command with custom python plug-inhttps://bugs.lttng.org/issues/13382021-12-02T21:39:41ZJérémie Galarneaujeremie.galarneau@efficios.com
<pre>
babeltrace2 convert -d --plugin-path=. input.aoc21
</pre>
<p>Results in a crash at</p>
<pre>
(gdb) bt
#0 0x00007fc325f61d22 in raise () from /usr/lib/libc.so.6
#1 0x00007fc325f4b862 in abort () from /usr/lib/libc.so.6
#2 0x000055882abffe3a in bt_common_abort () at common.c:2111
#3 0x000055882ac0d4ee in bt_config_convert_from_args (argc=argc@entry=3,
argv=argv@entry=0x7ffee7a2c538, cfg_out=cfg_out@entry=0x7ffee7a2c378, plugin_paths=0x55882cc26da0,
default_log_level=default_log_level@entry=0x7ffee7a2c2a4,
interrupter=interrupter@entry=0x55882cc26d60, consumed_args=1) at babeltrace2-cfg-cli-args.c:3606
#4 0x000055882ac123b0 in bt_config_cli_args_create (argc=argc@entry=5, argv=argv@entry=0x7ffee7a2c528,
cfg=cfg@entry=0x7ffee7a2c378, omit_system_plugin_path=omit_system_plugin_path@entry=false,
omit_home_plugin_path=<optimized out>, omit_home_plugin_path@entry=false,
initial_plugin_paths=initial_plugin_paths@entry=0x0, interrupter=0x55882cc26d60)
at babeltrace2-cfg-cli-args.c:4951
#5 0x000055882ac140d2 in bt_config_cli_args_create_with_default (argc=argc@entry=5,
argv=argv@entry=0x7ffee7a2c528, cfg=cfg@entry=0x7ffee7a2c378, interrupter=<optimized out>)
at babeltrace2-cfg-cli-args-default.c:70
#6 0x000055882abffef3 in main (argc=5, argv=0x7ffee7a2c528) at babeltrace2.c:2642
</pre>
<p>The current path (to which plugin-path points) contains a python plug-in.</p>
<pre>
import bt2
bt2.register_plugin(__name__, "aoc21")
class AOC21SourceValuesIterator(bt2._UserMessageIterator):
def __init__(self, config, output_port):
self._values_file = output_port.user_data[0]
self._ping_ec = output_port.user_data[1]
ping_sc = self._ping_ec.stream_class
tc = ping_sc.trace_class
trace = tc()
self._value_stream = trace.create_stream(ping_sc)
self._stream_begin_msg = self._create_stream_beginning_message(
self._value_stream
)
self._stream_end_msg = self._create_stream_end_message(self._value_stream)
def __next__(self):
if self._stream_begin_msg:
msg = self._stream_begin_msg
self._stream_begin_msg = None
return msg
try:
line = next(self._values_file)
except StopIteration:
if self._stream_end_msg:
msg = self._stream_end_msg
self._stream_end_msg
return msg
else:
raise StopIteration
event_msg = self._create_event_message(
self._ping_ec, self._value_stream, default_clock_snapshot=0
)
event_msg.event.payload_field["depth"] = int(line)
return event_msg
@bt2.plugin_component_class
class AOC21Source(
bt2._UserSourceComponent, message_iterator_class=AOC21SourceValuesIterator
):
def __init__(self, config, params, obj):
if "path" not in params:
raise ValueError("AOC21Source: missing `path` parameter")
path = params["path"]
if type(path) != bt2._StringValueConst:
raise TypeError(
"AOC21Source: expecting `path` parameter to be a string, got a {}".format(
type(path)
)
)
values_file = open(str(path), "r")
tc = self._create_trace_class()
cc = self._create_clock_class()
sc = tc.create_stream_class(default_clock_class=cc)
ping_event_payload = tc.create_structure_field_class()
ping_event_payload.append_member(
"depth", tc.create_unsigned_integer_field_class()
)
ping_event_ec = sc.create_event_class(
name="ping", payload_field_class=ping_event_payload
)
self._add_output_port("the-values", (values_file, ping_event_ec))
class WindowSum:
def __init__(self, size: int):
self._size = size
self._values = []
def add_value(self, value: int):
if len(self._values) >= 3:
raise RuntimeError
self._values.append(value)
@property
def is_full(self) -> bool:
return len(self._values) == 3
@property
def sum(self) -> int:
return sum(self._values)
def clear(self):
self._values.clear()
@bt2.plugin_component_class
class AOC21Sink(bt2._UserSinkComponent):
def __init__(self, config, params, obj):
self._port = self._add_input_port("holiday-spirit")
self._increase_count = 0
self._last_completed_window_sum = None
self._windows = []
def _user_graph_is_configured(self):
self._it = self._create_message_iterator(self._port)
def _user_consume(self):
msg = next(self._it)
if type(msg) is bt2._EventMessageConst:
depth = msg.event["depth"]
# Initialize windows one after the other to maintain an offset
# between them
if len(self._windows) < 3:
self._windows.append(WindowSum(3))
for window in self._windows:
window.add_value(depth)
if window.is_full:
if (
self._last_completed_window_sum
and window.sum > self._last_completed_window_sum
):
self._increase_count = self._increase_count + 1
self._last_completed_window_sum = window.sum
window.clear()
elif type(msg) is bt2._StreamEndMessageConst:
print(self._increase_count)
raise bt2.Stop
</pre> Babeltrace - Bug #1220 (New): filter.utils.trimmer component does not support streams without pac...https://bugs.lttng.org/issues/12202020-02-17T18:51:28ZSimon Marchisimon.marchi@polymtl.ca
<p>When trying to use a trimmer component with a stream that does not have packets, we get:</p>
<pre>
CAUSED BY [filter.utils.trimmer: 'filter.utils.trimmer'] (/home/smarchi/src/babeltrace/src/plugins/utils/trimmer/trimmer.c:1315)
Unsupported stream: packets have no beginning clock snapshot: stream-addr=0x60d000001080, stream-id=0, stream-name="(null)"
</pre>
<p>The trimmer component does not yet support packet messages that don't have default clock snapshots, but it should support streams that don't have packet messages at all.</p>
<p>It can be reproduced with the following plugin file:</p>
<pre>
import bt2
class MyIter(bt2._UserMessageIterator):
def __init__(self, config, port):
tc, sc, ec, cc = port.user_data
trace = sc.trace_class()
stream = trace.create_stream(sc)
self._msgs = [
self._create_stream_beginning_message(stream),
self._create_event_message(ec, stream, 123),
self._create_stream_end_message(stream),
]
self._i = 0
def __next__(self):
if self._i >= len(self._msgs):
raise bt2.Stop
msg = self._msgs[self._i]
self._i += 1
return msg
def _user_can_seek_beginning(self):
return True
def _user_seek_beginning(self):
self._i = 0
@bt2.plugin_component_class
class MySource(bt2._UserSourceComponent, message_iterator_class=MyIter):
def __init__(self, config, params, obj):
cc = self._create_clock_class()
tc = self._create_trace_class()
sc = tc.create_stream_class(default_clock_class=cc)
ec = sc.create_event_class(name='hello')
self._add_output_port('out', (tc, sc, ec, cc))
bt2.register_plugin(
__name__, "foo",
)
</pre>
<p>And the command line:</p>
<pre>babeltrace2 --plugin-path . -c source.foo.MySource -c filter.utils.trimmer</pre> Babeltrace - Bug #1168 (Feedback): CTF for a user-plugged clock assumes that "offset" is unsigned...https://bugs.lttng.org/issues/11682018-05-31T21:52:00ZVlad Roubtsov
<p>Hi,</p>
<p>I need to switch LTTng timestamp source to CLOCK_REALTIME from CLOCK_MONOTONIC in order to correlate with hardware-generated timestamps in a NIC. My initial attempt was easy enough to get going as a clock plugin:</p>
<pre><code class="cpp syntaxhl" data-language="cpp"><span class="k">static</span> <span class="kt">uint64_t</span>
<span class="nf">my_clock_time</span> <span class="p">()</span>
<span class="p">{</span>
<span class="k">struct</span> <span class="nc">timespec</span> <span class="n">t</span><span class="p">;</span>
<span class="n">clock_gettime</span> <span class="p">(</span><span class="n">CLOCK_REALTIME</span><span class="p">,</span> <span class="o">&</span> <span class="n">t</span><span class="p">);</span>
<span class="k">return</span> <span class="p">(</span><span class="n">t</span><span class="p">.</span><span class="n">tv_sec</span> <span class="o">*</span> <span class="mi">1000000000UL</span> <span class="o">+</span> <span class="n">t</span><span class="p">.</span><span class="n">tv_nsec</span><span class="p">);</span>
<span class="p">}</span>
<span class="k">static</span> <span class="kt">uint64_t</span>
<span class="nf">my_clock_freq</span> <span class="p">()</span>
<span class="p">{</span>
<span class="k">return</span> <span class="mi">1000000000UL</span><span class="p">;</span>
<span class="p">}</span>
</code></pre>
<p>(the rest follows the "clock-override" example). However, this results in sporadic errors opening the trace later via babeltrace:<br /><pre>
[error] ctf_clock_declaration_visit: unexpected unary expression for clock offset
[error] ctf_visitor_construct_metadata: clock declaration error
[error] Error in CTF metadata constructor -22
[warning] Unable to open trace metadata for path "/.../ust/pid/...-115227-20180601-062437".
[warning] [Context] Cannot open_trace of format ctf at path /...-115227-20180601-062437.
</pre></p>
<p>It appears that this happens when LTTng calculates the clock's "epoch offset" (which in theory should be 0 above) and it comes out as a small negative number. To reproduce this <em>every time</em>, try shifting the <code>my_clock_value()</code> result:</p>
<pre><code class="cpp syntaxhl" data-language="cpp"><span class="k">static</span> <span class="kt">uint64_t</span>
<span class="nf">my_clock_time</span> <span class="p">()</span>
<span class="p">{</span>
<span class="k">struct</span> <span class="nc">timespec</span> <span class="n">t</span><span class="p">;</span>
<span class="n">clock_gettime</span> <span class="p">(</span><span class="n">CLOCK_REALTIME</span><span class="p">,</span> <span class="o">&</span> <span class="n">t</span><span class="p">);</span>
<span class="k">return</span> <span class="p">(</span><span class="n">t</span><span class="p">.</span><span class="n">tv_sec</span> <span class="o">*</span> <span class="mi">1000000000UL</span> <span class="o">+</span> <span class="n">t</span><span class="p">.</span><span class="n">tv_nsec</span> <span class="o">+</span> <span class="mi">1000</span><span class="p">);</span>
<span class="p">}</span>
</code></pre>
<p>Peeking inside the persisted "metadata" you will see something like this:<br /><pre>
>hexdump -C /...-115227-20180601-062437/metadata | less
...
00000440 4c 54 49 4d 45 22 3b 0a 09 66 72 65 71 20 3d 20 |LTIME";..freq = |
00000450 31 30 30 30 30 30 30 30 30 30 3b 20 2f 2a 20 46 |1000000000; /* F|
00000460 72 65 71 75 65 6e 63 79 2c 20 69 6e 20 48 7a 20 |requency, in Hz |
00000470 2a 2f 0a 09 2f 2a 20 63 6c 6f 63 6b 20 76 61 6c |*/../* clock val|
00000480 75 65 20 6f 66 66 73 65 74 20 66 72 6f 6d 20 45 |ue offset from E|
00000490 70 6f 63 68 20 69 73 3a 20 6f 66 66 73 65 74 20 |poch is: offset |
000004a0 2a 20 28 31 2f 66 72 65 71 29 20 2a 2f 0a 09 6f |* (1/freq) */..o|
000004b0 66 66 73 65 74 20 3d 20 2d 31 30 30 31 3b 0a 7d |ffset = -1001;.}| <- negative value stored as "signed = false" int?
000004c0 3b 0a 0a 74 79 70 65 61 6c 69 61 73 20 69 6e 74 |;..typealias int|
000004d0 65 67 65 72 20 7b 0a 09 73 69 7a 65 20 3d 20 32 |eger {..size = 2|
000004e0 37 3b 20 61 6c 69 67 6e 20 3d 20 31 3b 20 73 69 |7; align = 1; si|
000004f0 67 6e 65 64 20 3d 20 66 61 6c 73 65 3b 0a 09 6d |gned = false;..m|
</pre></p>
<p>My env details (both lttng and babeltrace were built from stable sources):<br /><pre>
>lttng --version
lttng (LTTng Trace Control) 2.10.4 - KeKriek
>lttng-sessiond --version
2.10.4
>babeltrace --version
BabelTrace Trace Viewer and Converter 1.5.5
>uname -a
Linux ... 3.10.0-693.11.6.el7.x86_64 #1 SMP Thu Jan 4 01:06:37 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
>cat /etc/system-release
CentOS Linux release 7.4.1708 (Core)
>nproc
16
</pre></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 #1138 (New): Live session listing return malformed urlhttps://bugs.lttng.org/issues/11382017-11-20T16:47:11ZJonathan Rajotte Julienjonathan.rajotte-julien@efficios.com
<p>On stable 1.5, not tested against master.</p>
<p>While querying a relayd:</p>
<p>Good output:<br /><pre>
babeltrace -i lttng-live net://localhost
</pre><br />Yield correctly:<br /><pre>
net://localhost/host/psrcode-TP-X230/auto-20171120-114204 (timer = 1000000, 0 stream(s), 0 client(s) connected)
</pre></p>
<p>While:<br /><pre>
babeltrace -v -i lttng-live net://localhost/host/psrcode-TP-X230
</pre></p>
<p>Yield incorrectly:<br /><pre>
net://localhost/host/psrcode-TP-X230/host/psrcode-TP-X230/auto-20171120-114204 (timer = 1000000, 0 stream(s), 0 client(s) connected)
</pre></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>