LTTng bugs repository: Issueshttps://bugs.lttng.org/https://bugs.lttng.org/themes/lttng/favicon/a.ico?14249722912023-04-25T11:44:50ZLTTng bugs repository
Redmine LTTng-tools - Bug #1372 (In Progress): Consumer crashes during rotation (write to bad file descri...https://bugs.lttng.org/issues/13722023-04-25T11:44:50ZMaximilian Fickert
<p>Hi,</p>
<p>We are observing seemingly random crashes in the LTTng consumer daemon when tracing a C++ application with LTTng-UST. Our workload has a single <code>printf</code>-like tracepoint, where each string is in the order of 1kb and the total output is around 30MB/s. LTTng is set up with a single session and channel enabling this tracepoint, and we enabled rotation with a maximum size of 100MB or every 30 seconds. We are periodically starting new traced processes and the system runs close to 100% CPU load. This ran on an AWS Graviton2 (ARM) instance with CentOS 7 and a 5.4 kernel, using LTTng-UST 2.13.5 and LTTng-tools 2.13.8.</p>
<p>The first reported error is a write to a bad file descriptor (-1), apparently when waking up the metadata poll thread during a rotation.</p>
<p>I looked through the LTTng logs with <code>-vvv --verbose-consumer</code> and I suspect this might be caused by some sort of race condition; looking at the following log fragments (I inserted two additional debug lines in LTTng so the line numbers may not exactly match those in the 2.13.8 source code):<br /><pre>
DBG1 - 15:12:12.865621802 [Rotation]: Consumer rotate channel key 574 (in consumer_rotate_channel() at consumer.c:1694)
</pre><br />A rotation is requested for the channel with key 574. Then the metadata pipe of this channel is closed:<br /><pre>
DBG3 - 15:12:13.269805401 [UST application management]: Buffer registry per PID find id: 288 (in buffer_reg_pid_find() at buffer-registry.c:308)
DBG3 - 15:12:13.269811366 [UST application management]: No metadata to push for metadata key 574 (in ust_app_push_metadata() at ust-app.c:689)
DBG2 - 15:12:13.269816979 [UST application management]: Consumer close metadata channel key 574 (in consumer_close_metadata() at consumer.c:1394)
DBG1 - 15:12:13.269826899 [6593/6605]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3283)
DBG1 - 15:12:13.269835259 [6593/6605]: UST consumer close metadata key 574 (in close_metadata() at ust-consumer.c:804)
DBG1 - 15:12:13.269838591 [6593/6605]: Closing metadata channel key 574 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:3235)
DBG3 - 15:12:13.269841167 [6593/6605]: close() fd = 603 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:3250)
DBG1 - 15:12:13.269847075 [6593/6605]: Received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3299)
</pre><br />But then LTTng unsuccessfully attempts to wake up the metadata poll thread by writing to the file descriptor that was just closed (the <code>channel key = 574</code> in the metadata poll thread message below is <code>channel->key</code>):<br /><pre>
DBG1 - 15:12:13.271001175 [6593/6605]: Waking up metadata poll thread (writing to pipe): channel name = 'metadata', channel key = 574 (in consumer_metadata_wakeup_pipe() at consumer.c:888)
DBG3 - 15:12:13.271010093 [6593/6605]: write() fd = -1 (in consumer_metadata_wakeup_pipe() at consumer.c:892)
PERROR - 15:12:13.271014655 [6593/6605]: Failed to write to UST metadata pipe while attempting to wake-up the metadata poll thread: Bad file descriptor (in consumer_metadata_wakeup_pipe() at consumer.c:907)
Error: Failed to dump the metadata cache
Error: Rotate channel failed
</pre><br />After this, there are a bunch more errors in the logs, but I guess they are ultimately caused by the issue above:<br /><pre>
DBG1 - 15:12:13.273572566 [6593/6604]: Consumer mmap write() ret 446464 (len 446464) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1726)
lttng-consumerd: consumer.c:1639: lttng_consumer_on_read_subbuffer_mmap: Assertion `stream->net_seq_idx != (uint64_t) -1ULL || stream->trace_chunk' failed.
...
DBG1 - 15:12:13.475559588 [Consumer management]: Error when receiving data from the consumer socket 61 (in consumer_socket_recv() at consumer.c:159)
Error: Handling metadata request
DBG1 - 15:12:13.476382551 [Rotation]: Error when receiving data from the consumer socket 60 (in consumer_socket_recv() at consumer.c:159)
Error: Error pushing metadata to consumer
DBG1 - 15:12:13.476418727 [Rotation]: Consumer rotate channel key 604 (in consumer_rotate_channel() at consumer.c:1694)
DBG1 - 15:12:13.476424962 [Rotation]: Setting trace chunk close command to "move to completed chunk folder" (in lttng_trace_chunk_set_close_command() at trace-chunk.c:1797)
DBG1 - 15:12:13.476428671 [Rotation]: lttng_trace_chunk_rename_path from .tmp_new_chunk to (null) (in lttng_trace_chunk_rename_path_no_lock() at trace-chunk.c:755)
DBG3 - 15:12:13.476437516 [Rotation]: renameat() old_dirfd = 946, old_name = .tmp_new_chunk, new_dirfd = 946, new_name = 20230421T151158+0000-5, uid = 1004, gid = 1004 (in run_as_renameat() at runas.c:1883)
DBG1 - 15:12:13.476444999 [Rotation]: Using run_as worker (in run_as() at runas.c:1646)
Error: Error pushing metadata to consumer
DBG2 - 15:12:13.476569797 [UST application management]: Consumer close metadata channel key 624 (in consumer_close_metadata() at consumer.c:1394)
DBG1 - 15:12:13.476585469 [UST application management]: PID 7729 unregistering with sock 1060 (in ust_app_unregister() at ust-app.c:4253)
DBG1 - 15:12:13.476589957 [UST application management]: Flushing app session buffers for ust app pid 7729 (in ust_app_flush_app_session() at ust-app.c:5315)
DBG2 - 15:12:13.476611364 [UST application management]: Consumer flush channel key 651 (in consumer_flush_channel() at consumer.c:1328)
Error: Error flushing consumer channel
DBG3 - 15:12:13.476616188 [UST application management]: Buffer registry per PID find id: 327 (in buffer_reg_pid_find() at buffer-registry.c:308)
DBG3 - 15:12:13.476620406 [UST application management]: No metadata to push for metadata key 652 (in ust_app_push_metadata() at ust-app.c:689)
DBG2 - 15:12:13.476623277 [UST application management]: Consumer close metadata channel key 652 (in consumer_close_metadata() at consumer.c:1394)
DBG1 - 15:12:13.476633312 [UST application management]: PID 11467 unregistering with sock 457 (in ust_app_unregister() at ust-app.c:4253)
DBG1 - 15:12:13.476636996 [UST application management]: Flushing app session buffers for ust app pid 11467 (in ust_app_flush_app_session() at ust-app.c:5315)
DBG2 - 15:12:13.476640508 [UST application management]: Consumer flush channel key 661 (in consumer_flush_channel() at consumer.c:1328)
Error: Error flushing consumer channel
DBG3 - 15:12:13.476643946 [UST application management]: Buffer registry per PID find id: 332 (in buffer_reg_pid_find() at buffer-registry.c:308)
DBG2 - 15:12:13.476649501 [UST application management]: Consumer push metadata to consumer socket -1 (in consumer_push_metadata() at consumer.c:1462)
Error: Error pushing metadata to consumer
...
</pre></p>
<p>We currently do not have simple steps to reliably reproduce the issue, but this happens somewhat irregularly after 5-10 minutes (sometimes earlier, sometimes later) of running our workload. I attached a longer fragment of the logs around the time the error happens, let us know if we can provide any more information to help.</p> LTTng - Bug #1370 (Confirmed): Why "lttng create --live" spawns a local relay daemon but not in ...https://bugs.lttng.org/issues/13702023-04-06T15:33:05ZBin Yuan
<p>The relayd spawned by lttng-create command don't close the file descriptor such like stdout.<br />Why not spawn the relayd with "--daemonize" option.</p> LTTng - Bug #1298 (On pause): LTTng build reprudibility for OE-core (yocto)https://bugs.lttng.org/issues/12982021-03-01T14:52:11ZJonathan Rajotte Julienjonathan.rajotte-julien@efficios.com
<p>Currently the installable part of LTTng are "reproducible" for the Debian packages.</p>
<p>Still, oe-core are having issues since they seems to be also shipping the tests for ptest.</p>
<p>See <a class="external" href="https://autobuilder.yocto.io/pub/repro-fail/2021-2-25-rp/lttng-tools/diff/">https://autobuilder.yocto.io/pub/repro-fail/2021-2-25-rp/lttng-tools/diff/</a></p>
<p>As of today this is not a high priority for us. This will be revisited after 2.13 is released.</p> Babeltrace - Bug #1225 (On pause): src.ctf.lttng-live: `sessions` query error reportinghttps://bugs.lttng.org/issues/12252020-02-17T21:07:37ZFrancis Deslauriersfrancis.deslauriers@efficios.com
<p>The right format to query the list of sessions is:<br /><pre>
babeltrace2 query -p 'url="net://127.0.0.1"' src.ctf.lttng-live sessions
</pre></p>
<p>When adding a `/` at the end of the URL (by mistake maybe) you get the following error:<br /><pre>
10-23 10:11:25.193 2096 2096 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER parse_url@viewer-connection.c:127 [lttng-live] Invalid LTTng live URL format: Expecting `/host/` after hostname or port
10-23 10:11:25.193 2096 2096 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_connect_viewer@viewer-connection.c:253 [lttng-live] Failed to parse URL
10-23 10:11:25.193 2096 2096 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER live_viewer_connection_create@viewer-connection.c:1629 [lttng-live] Failure to establish connection: url="net://127.0.0.1/"
10-23 10:11:25.193 2096 2096 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_query_list_sessions@lttng-live.c:1589 [lttng-live] Failed to create viewer connection
10-23 10:11:25.193 2096 2096 W LIB/QUERY-EXECUTOR bt_query_executor_query@query-executor.c:246 Component class's "query" method failed: query-exec-addr=0x5625255fd7a0, cc-addr=0x5625255f80a0, cc-type=SOURCE, cc-name="lttng-live", cc-partial-descr="Connect to an LTTng relay daemon", cc-is-frozen=0, cc-so-handle-addr=0x5625255f7270, cc-so-handle-path="/usr/local/lib/babeltrace2/plugins/babeltrace-plugin-ctf.so", object="sessions", params-addr=0x5625255e4540, params-type=MAP, params-element-count=1, log-level=WARNING
10-23 10:11:25.193 2096 2096 E CLI cmd_query@babeltrace2.c:727 Failed to query component class: unknown error: plugin-name="ctf", comp-cls-name="lttng-live", comp-cls-type=1 object="sessions"
ERROR: [Babeltrace CLI] (babeltrace2.c:727)
Failed to query component class: unknown error: plugin-name="ctf", comp-cls-name="lttng-live", comp-cls-type=1
object="sessions"
CAUSED BY [Babeltrace library] (query-executor.c:246)
Component class's "query" method failed: query-exec-addr=0x5625255fd7a0, cc-addr=0x5625255f80a0, cc-type=SOURCE,
cc-name="lttng-live", cc-partial-descr="Connect to an LTTng relay daemon", cc-is-frozen=0,
cc-so-handle-addr=0x5625255f7270, cc-so-handle-path="/usr/local/lib/babeltrace2/plugins/babeltrace-plugin-ctf.so",
object="sessions", params-addr=0x5625255e4540, params-type=MAP, params-element-count=1, log-level=WARNING
CAUSED BY ['source.ctf.lttng-live'] (lttng-live.c:1589)
Failed to create viewer connection
CAUSED BY ['source.ctf.lttng-live'] (viewer-connection.c:1629)
Failure to establish connection: url="net://127.0.0.1/"
CAUSED BY ['source.ctf.lttng-live'] (viewer-connection.c:253)
Failed to parse URL
CAUSED BY ['source.ctf.lttng-live'] (viewer-connection.c:127)
Invalid LTTng live URL format: Expecting `/host/` after hostname or port
</pre><br />Suggesting to add the `/host/` part of the URL as if we were trying to connect to a session.<br />When in fact, since I am in a query, I would want it to be suggesting me to remove the extra `/` if anything.</p> LTTng - Bug #1177 (Confirmed): Document --pidfile of lttng-sessiond executablehttps://bugs.lttng.org/issues/11772019-03-05T19:00:20ZJonathan Rajotte Julienjonathan.rajotte-julien@efficios.com
<p>All is in title.</p>
<p>For anyone that receive all issue created, we had a db problem on upgrade to redmine 4.0 hence why I created it again.</p> LTTng-tools - Feature #1137 (Confirmed): Version handshake for lttng-consumerd and lttng-sessiondhttps://bugs.lttng.org/issues/11372017-11-15T23:37:32ZJonathan Rajotte Julienjonathan.rajotte-julien@efficios.com
Scenario:
<ul>
<li>User installed both a 32bit and 64 bit version of lttng-tools 2.X.</li>
<li>User uses in script lttng-session --consumerd32-path= --consumerd64-path=</li>
<li>User update the 64bit version to lttng-tools 2.(X+1) without upgrading</li>
<li>User still uses it's script but with the lttng-sessiond bin from lttng-tools 2.(X+1)</li>
</ul>
<p>Currently the consumerd and sessiond do not exchange version information hence we end up with undefined behaviour.</p>
<p>The version numbering might be coupled with the version of lttng but it is most probably wiser to use a separate versioning.</p> LTTng-tools - Bug #1128 (Confirmed): Contexts can be added multiple times to a kernel channelhttps://bugs.lttng.org/issues/11282017-08-03T02:48:03ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>The session daemon checks for duplicate user space contexts being enabled on a user space channel (using trace_ust_match_context()). A similar check is missing for kernel channels, allowing users to add the same context multiple times.</p>
<p><em>Extract from a session profile demonstrating the problem:</em><br /><pre>
<domain>
<type>KERNEL</type>
<buffer_type>GLOBAL</buffer_type>
<channels>
<channel>
<name>lol</name>
<enabled>true</enabled>
<overwrite_mode>DISCARD</overwrite_mode>
<subbuffer_size>1048576</subbuffer_size>
<subbuffer_count>4</subbuffer_count>
<switch_timer_interval>0</switch_timer_interval>
<read_timer_interval>200000</read_timer_interval>
<output_type>SPLICE</output_type>
<tracefile_size>0</tracefile_size>
<tracefile_count>0</tracefile_count>
<live_timer_interval>4294967295</live_timer_interval>
<monitor_timer_interval>1000000</monitor_timer_interval>
<blocking_timeout>0</blocking_timeout>
<events/>
<contexts>
<context>
<type>PID</type>
</context>
<context>
<type>PID</type>
</context>
<context>
<type>PID</type>
</context>
<context>
<type>PID</type>
</context>
<context>
<type>PID</type>
</context>
<context>
<type>PID</type>
</context>
<context>
<type>PID</type>
</context>
</contexts>
</channel>
</channels>
<trackers/>
</domain>
</pre></p> LTTng-tools - Bug #1102 (In Progress): Trigger conditions are not evaluated on subscriptionhttps://bugs.lttng.org/issues/11022017-05-11T22:43:22ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>Trigger conditions are not evaluated on subscription of a client. In the case of buffer usage conditions, this provides no way for clients to know the current state of the buffers.</p> LTTng-modules - Bug #938 (Confirmed): Enabling two events with same name but not the same event t...https://bugs.lttng.org/issues/9382015-09-15T17:10:43ZJonathan Rajotte Julienjonathan.rajotte-julien@efficios.com
<pre>
sudo lttng-sessiond -d
lttng create mysession
lttng enable-event --kernel kmem_kfree --probe sys_open+0xE
lttng enable-event --kernel kmem_kfree
lttng start
sleep 0.1
lttng stop
lttng view
</pre>
<p>Only the probe is considered when tracing. The metadata only shows the probe event.</p>
<p>This is a kernel tracer side problem (name as event key). A solution could be to prefix certain type of event on enable thus creating namespace e.g: probe_kmem_kfree.</p> LTTng - Bug #934 (Confirmed): Session in snapshot mode does not indicate a path when listedhttps://bugs.lttng.org/issues/9342015-09-06T03:23:30ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>The LTTng client does not indicate the default snapshot output path when listing a snapshot session.<br />It should either omit the "Trace path:", or indicate the default snapshot output path.</p>
<pre>
$ lttng create snap --snapshot
Session snap created.
Default snapshot output set to: /home/jgalar/lttng-traces/snap-20150905-232023
Snapshot mode set. Every channel enabled for that session will be set in overwrite mode and mmap output.
$ lttng list snap
Tracing session snap: [inactive snapshot]
Trace path:
</pre> LTTng-tools - Bug #901 (In Progress): Some liblttng-ctl don't return LTTNG_OK on successhttps://bugs.lttng.org/issues/9012015-08-05T18:26:10ZJérémie Galarneaujeremie.galarneau@efficios.com
<p>It appears that some liblttng-ctl functions, such as lttng_create_session_snapshot() have conflicting return code conventions.</p>
<p>In this specific case, the header under lttng/session.h asserts that the function will<br /><pre>
/*
[...]
* Return 0 on success else a negative LTTng error code.
*/
</pre></p>
<p>while the header in lttng-ctl.c affirms that it<br /><pre>
/*
[...]
* Returns LTTNG_OK on success or a negative error code.
*/
</pre></p>
<p>and the function actually returns<br /><pre>
ret = lttng_ctl_ask_sessiond_varlen(&lsm, uris, ...
</pre></p>
<p>which, itself will<br /><pre>
/*
[...]
Return size of data (only payload, not header) or a negative error code.
*/
</pre></p>
<p>This pattern is used in multiple places which breaks code which checks for "ret == LTTNG_OK" instead of "ret < 0".</p> LTTng-tools - Bug #833 (Confirmed): memcpy of non-packed struct into packed struct (possible layo...https://bugs.lttng.org/issues/8332014-09-09T13:17:10ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>lttng-tools src/lib/lttng-ctl/lttng-ctl.c:</p>
<p>lttng_enable_event_with_exclusions()</p>
<p>memcpy(&lsm.u.enable.event, ev, sizeof(lsm.u.enable.event));</p>
<p>copy "ev" (non-packed) into a packed structure.</p>
<p>We should copy each field one by one (create a copy_event_to_event_packed() helper to do so).</p> LTTng-tools - Bug #752 (In Progress): Output paths need better handling than truncationhttps://bugs.lttng.org/issues/7522014-03-07T21:33:50ZDaniel U. Thibaultdaniel.thibault@drdc-rddc.gc.ca
For instance, in the aftermath of <code>lttng-tools/src/bin/lttng-sessiond/cmd.c:record_ust_snapshot</code>, the <code>msg.u.snapshot_channel.pathname</code> is limited to PATH_MAX (typically 4096) but is built with <code>"%s/%s-%s-%" PRIu64 "%s"</code>, where the successive arguments are (discounting the closing nulls):
<ul>
<li><code>output->consumer->dst.trace_path</code> PATH_MAX - 1 (no trailing /)</li>
<li>/ 1</li>
<li><code>output->name</code> NAME_MAX - 1</li>
<li>- 1</li>
<li><code>output->datetime</code> 15</li>
<li>- 1</li>
<li><code>output->nb_snapshot</code> 20 digits (unsigned 64-bit integer)</li>
<li><code>session_path</code> PATH_MAX - 1 (including leading and trailing /)</li>
</ul>
<p>The worst-case <code>session_path</code> part is <code>'/ust/pid/<proc>-<vpid>-<datetime>/'</code> so it's actually limited to 12+15+5+15 = 47 characters (<code>/proc/PID/status.name</code> is truncated to 15 characters, and VPID is unsigned 16-bit for 5 characters) (closing null excluded). So one solution would be to limit the <code>consumer->dst.trace_path</code> to PATH_MAX - (NAME_MAX - 1 + 15 + 20 + 47 + 3) - 1 (for the null). However, if we want the path+filetitles of the channel files to fit in PATH_MAX, we need to chop another NAME_MAX off (and also limit channel names to NAME_MAX - (1 + 5 + 1 + 10 + 1) [underscore, 16-bit unsigned CPU ID, underscore, 32-bit unsigned chunk number, null] so they fit).</p>
<p>Truncation remains nevertheless possible, and would wreak havoc with the trace output tree. <code>Babeltrace</code> and the user count on proper folder and file tree structure to manage their traces. The code needs to detect instances of truncation and report them as errors.</p>
<p>As an aside, the snapshot output name should be limited to MAX_PATH - (1+10) because it gets suffixed with a hyphen and an unsigned 32-bit integer (the output set sequential ID).</p> LTTng-tools - Feature #749 (Confirmed): lttng list <session> should list the contexts added to ea...https://bugs.lttng.org/issues/7492014-03-07T16:36:19ZDaniel U. Thibaultdaniel.thibault@drdc-rddc.gc.ca
<p>It would be nice if the <code>lttng list <session></code> command listed the context currently added to each channel. Currently, it does not mention context at all.</p> LTTng-UST - Feature #327 (On pause): Implement missing hostname contexthttps://bugs.lttng.org/issues/3272012-08-26T23:22:47ZMathieu Desnoyersmathieu.desnoyers@efficios.com
<p>To match features of lttng-modules.</p>