Jonathan Rajotte [Tue, 19 May 2020 16:23:18 +0000 (12:23 -0400)]
Fix: common: abort on rotation after time manipulation
Observed issue
==============
Core dump:
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x0000003eb4025548 in __GI_abort () at abort.c:79
#2 0x0000003eb402542f in __assert_fail_base (fmt=0x3eb4184ae0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x4cdee0 "(trace_chunk->timestamp_close).is_set",
file=0x4cde78 "../../../lttng-tools-2.11.3/src/common/trace-chunk.c", line=903, function=0x4cf4a0 <__PRETTY_FUNCTION__.6756> "lttng_trace_chunk_move_to_completed")
at assert.c:92
#3 0x0000003eb4033af2 in __GI___assert_fail (assertion=assertion@entry=0x4cdee0 "(trace_chunk->timestamp_close).is_set",
file=file@entry=0x4cde78 "../../../lttng-tools-2.11.3/src/common/trace-chunk.c", line=line@entry=903,
function=function@entry=0x4cf4a0 <__PRETTY_FUNCTION__.6756> "lttng_trace_chunk_move_to_completed") at assert.c:101
#4 0x000000000047f37e in lttng_trace_chunk_move_to_completed (trace_chunk=0x7fcb5c00e570) at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:903
#5 0x0000000000480755 in lttng_trace_chunk_release (ref=0x7fcb5c00e598) at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1117
#6 urcu_ref_put (release=<optimized out>, ref=0x7fcb5c00e598) at /usr/include/urcu/ref.h:68
#7 lttng_trace_chunk_put (chunk=0x7fcb5c00e570) at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1150
#8 0x0000000000429c22 in cmd_rotate_session (session=0x7fcb5c003ff0, rotate_return=rotate_return@entry=0x7fcb6b7ed470, quiet_rotation=quiet_rotation@entry=false)
at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/cmd.c:5037
#9 0x00000000004451d7 in process_client_msg (cmd_ctx=0x7fcb5c00e760, sock=sock@entry=0x7fcb6b7fd4c0, sock_error=sock_error@entry=0x7fcb6b7fd4c4)
at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/client.c:1852
#10 0x00000000004474c6 in thread_manage_clients (data=<optimized out>) at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/client.c:2199
#11 0x00000000004422f2 in launch_thread (data=0x4f97a0) at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/thread.c:75
#12 0x0000003eb4408ed4 in start_thread (arg=<optimized out>) at pthread_create.c:479
#13 0x0000003eb40f8e6f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Reproduction:
Disable ntp/any time management mechanism.
lttng create
lttng enable-event -u 'lttng_ust_tracef:*'
lttng start
lttng rotate
date --set="$(date --date='-1 hour')"
lttng rotate auto-20200515-142503
Waiting for rotation to complete
Error: Failed to query the state of the rotation.
Logs:
DEBUG1 - 12:25:28.570037987 [2660/2717]: Setting trace chunk close command to "move to completed chunk folder" (in lttng_trace_chunk_set_close_command() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1073)
Error: Failed to set trace chunk close timestamp: close timestamp is before creation timestamp
Error: Failed to set the close timestamp of the current trace chunk of session "auto-20200515-142503"
lttng-sessiond: ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:903: lttng_trace_chunk_move_to_completed: Assertion `(trace_chunk->timestamp_close).is_set' failed.
...
Aborted (core dumped)
root@X10SDV-8C-TLN4F:~# DEBUG1 - 12:25:29.534263017 [2739/2739]: Releasing trace chunk registry to all trace chunks (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1414)
DEBUG1 - 12:25:29.534317468 [2739/2739]: Releasing reference to trace chunk: session_id = 0chunk_id = 2, name = "20200515T122528+0000-2", status = closed (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1435)
DEBUG1 - 12:25:29.534365653 [2739/2739]: Releasing reference to trace chunk: session_id = 0chunk_id = 1, name = "20200515T142520+0000-1", status = closed (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1435)
DEBUG1 - 12:25:29.534400638 [2739/2739]: Released reference to 2 trace chunks in lttng_trace_chunk_registry_put_each_chunk() (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1447)
Error: 2 trace chunks are leaked by lttng-consumerd. This can be caused by an internal error of the session daemon.
Cause
=====
The trace_chunk->timestamp_close is not set since the result from time()
is smaller than the creation timestamp.
The close timestamp is smaller because the calendar system time is
modified by an administrator.
time() offers no monotonicity guarantee and hence is exposed to time
modification of the system.
The begin and close timestamps are strictly used in the name generation
of the chunk/archives. Given the current usage of these timestamps
validating monotonicity should not be a fatal error. Name uniqueness is
provided by the chunk name suffix (auto increment).
Solution
========
Do not enforce monotonicity for the begin and close timestamps but warn
on unexpected return (begin > close).
Known drawbacks
=========
None.
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ic4b17285d150358d1569d6821c451c243e64e9a1
I get the following warning when compiling with `-Wall -Werror` with gcc
9.3.0:
In file included from ../../src/common/macros.h:15,
from ../../src/common/lttng-kernel.h:14,
from ../../src/bin/lttng-sessiond/trace-kernel.h:14,
from test_kernel_data.c:16:
In function ‘lttng_strnlen’,
inlined from ‘lttng_strncpy’ at ../../src/common/macros.h:120:6,
inlined from ‘test_create_kernel_event’ at test_kernel_data.c:136:2:
../../src/common/compat/string.h:28:8: error: ‘memchr’ reading 256 bytes from a region of size 11 [-Werror=stringop-overflow=]
28 | end = memchr(str, 0, max);
| ^~~~~~~~~~~~~~~~~~~
Fix this warning by using the RANDOM_STRING_LEN value as the max number
of bytes to copy.
Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Change-Id: I61752ee17163c4d642aad21b296c0fc4fad5b7a6
(cherry picked from commit 1dd622b10db0821d77490c937caee80c65332f14) Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Here we load a xml created by lttng-tools-2.12 and try to load it using
lttng-tools 2.11. We expect this to fail on the load.
The command report an error on the stderr but the command return code
value is zero.
From lttng-ivc test runtime.log:
Command #0
Return value: 0
Command: lttng load --input-path=/home/joraj/lttng/lttng-ivc/.tox/py3/tmp/test_save_load_blocking_timeou0/save_load saved_trace
STDOUT:
Session saved_trace has been loaded successfully
STDERR:
XML Error: Element 'process_attr_trackers': This element is not expected.
Error: Session configuration file validation failed
Cause
==============
The error coming from load_session_from_file is not handled correctly.
Solution
========
Rework error handling in load_session_from_path and
load_session_from_file.
LTTNG_ERR_LOAD_SESSION_NOENT is NOT an error when session_name is
specified in load_session_from_path. In this scenario, we are actively
looking for the configuration of the session.
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I0fea474045b718664e70ffe169e4e4fa125791a8
Fix: lttng-destroy: missing newline on session destruction message
The lost packets/discarded events statistics are printed on the same
line as the session destruction progress message when the session is
stopped as part of the `destroy` command.
This is a consequence of printing the statistics as they are
retrieved; the statistics must be fetched before the destruction,
but the progress indicator is still being printed.
The statistics output is now formatted to a buffer and printed
after the session's destruction has completed.
Simon Marchi [Wed, 25 Mar 2020 22:39:30 +0000 (18:39 -0400)]
Fix: common: add `void` parameter to log_add_time declaration
It makes it match the definition and fixes this warning:
CC error.lo
/home/smarchi/src/lttng-tools/src/common/error.c:33:13: error: no previous prototype for ‘log_add_time’ [-Werror=missing-prototypes]
const char *log_add_time(void)
^~~~~~~~~~~~
Change-Id: Ibbf5eebd8171504bc7050c754e2a5d113b6b5387 Signed-off-by: Simon Marchi <simon.marchi@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: lttng-list: don't warn when the kernel domain has no channels
Some commands beside lttng-enable-channel have the side-effect of
creating a domain. For instance, the lttng-track and lttng-untrack
commands will implicitly create their target domains if they don't
exist. Thus, it is not unexpected for a domain to exist without
channels.
Currently, tracking process attributes in the user space and kernel
domains will result in a warning being printed when lttng-status
(or lttng-list `the_session`) is invoked.
Example output:
Tracing session arielle_bolduc: [inactive]
Trace output: /home/jgalar/lttng-traces/arielle_bolduc-20200323-191128
=== Domain: Linux kernel ===
Tracked process attributes
Process IDs: all
Virtual Process IDs: 12365, 526, 41
User IDs: all
Virtual User IDs: all
Group IDs: all
Virtual Group IDs: all
Warning: No kernel channel
=== Domain: User space ===
Buffering scheme: per-user
Tracked process attributes
Virtual Process IDs: 12365, 526, 41
Virtual User IDs: all
Virtual Group IDs: all
The warning is removed since it can only confuse users.
Fix: sessiond: occasional badfd error on repeated SIGTERM
The session daemon occasionally prints the following messages
when it received multiple SIGTERM signals:
PERROR - 16:50:18.505585257 [49845/49845]: write poll pipe: Bad file
descriptor (in notify_thread_pipe() at utils.c:35)
This is caused by a (somewhat inevitable) race between the teardown of
the daemon and the closing of its quit pipe. This happens more often
when kernel modules take a long time to be unloaded and the user
spams ctrl+c in the hope of convincing the daemon process to close
faster since modules are unloaded after closing the quit pipe.
Setting closed pipe fds to '-1' is safe anyway and is already
handled by the notify_thread_pipe() util.
Fix: lttng: incorrect domain list printed when no domain is provided
The following commands make use of a common utility function to
validate the count of domains specified and print an error when it
is invalid:
- lttng-enable-event,
- lttng-disable-event,
- lttng-track,
- lttng-untrack,
- lttng-add-context,
- lttng-enable-channel,
- lttng-disable-channel.
Those commands do not allow the same domains to be used. In fact, they
all expect --kernel or --userspace only, except for the
lttng-enable-event, lttng-disable-event, and lttng-add-context
commands which allow the --log4j, --jul, and --python domain options
to be used.
Currently, the error message when no domain is specified is incorrect
for all of those commands. The error reads as follows:
`Error: Please specify a domain (-k/-u/-j).`
For most commands, the -j option cannot be used. For those that allow
agent domains, the message is missing the -l and -p domains.
This ensures that the expected domains are printed for each of those
commands.
Moreover, the message is clarified by using the long form option
names.
Fix: relayd: use of relay_session ref count before initialization
The relay_session's reference count is used before it is initialized
on multiple code paths of session_create(). The initialization of the
reference count, mutexes, and intrusive data structure nodes are
initialized earlier to make their use safe in the event of an error.
Issue
=====
With the current implementation, when calling the `wait_on_file()`
function with the `file_exist` parameter set to false the function will
return even if the target file exists.
In a scenario where we enter the loop and the targer file exist, the
first call to `stat()` will return 0 and will not enter any of the `if`
and break from the loop directly.
Solution
========
If the file exists, only break from the loop if it's the desired exit
condition.
Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Change-Id: Ia3e9c41a2a515815d3ff931d8f7c1c14a52b31ae Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: force the use of our _FORTIFY_SOURCE definition
Some toolset (ubuntu) already defined the _FORTIFY_SOURCE.
This removes the warning we see if this is the case. Unset the variable and
reset it.
The warning:
make[3]: Entering directory '/home/joraj/lttng/master/lttng-tools/tests/regression/kernel'
CC select_poll_epoll-select_poll_epoll.o
<command-line>: warning: "_FORTIFY_SOURCE" redefined
<built-in>: note: this is the location of the previous definition
CCLD select_poll_epoll
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Change-Id: I2fa0482afa8941705a992f62a2e63657ea9e2b87 Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
The snapshot record command is implemented by creating and setting
a new trace chunk on the target session, capturing the snapshot, and
closing the session's trace chunk once it is complete.
On some error paths, the session's newly created trace chunk is not
cleared. This means that the session is seen to have a
'current_trace_chunk' on the next attempt to record a snapshot; an
unexpected condition for which an assert() exists.
This results in the following crash:
lttng-sessiond: /home/smarchi/src/lttng-tools/src/bin/lttng-sessiond/cmd.c:4685: snapshot_record: Assertion `!session->current_trace_chunk' failed.
Ensure that the session's current trace chunk is closed and cleared
when an error occurs during the command's execution.
Fix: sessiond: bounded snapshot record fails when no streams exist
Attempting to record a snapshot with a `--max-size` fails when no
streams exist. For instance, attempting to record a snapshot for a
user space session when no applications are running will fail with the
following output:
Error: Invalid snapshot size. Cannot fit at least one packet per stream.
Error: Snapshot max size is invalid
The function get_session_nb_packets_per_stream() computes an
approximation of the number of packets to capture to honor the maximal
size specified. However, at the end, it doesn't distinguish between
'0' meaning that "no packets can be captured" (no streams exist) and
'0' meaning that "the max size is too small to accomodate one packet".
Those two cases can be distinguished by checking if the 'size_left' is
still the 'max_size', meaning that not even the size of one packet was
substracted from 'max_size'.
Reported-by: Simon Marchi <simark@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I5caef9ce926bbc7143a90667749ffaed972590c1
Simon Marchi [Wed, 15 Jan 2020 20:42:31 +0000 (15:42 -0500)]
Fix: include stdlib.h in compat/string.h
Fixes:
CC uuid.lo
In file included from /home/smarchi/src/lttng-tools/src/common/uuid.c:19:0:
/home/smarchi/src/lttng-tools/src/common/compat/string.h: In function ‘lttng_strndup’:
/home/smarchi/src/lttng-tools/src/common/compat/string.h:78:8: error: implicit declaration of function ‘malloc’ [-Werror=implicit-function-declaration]
ret = malloc(navail);
^~~~~~
/home/smarchi/src/lttng-tools/src/common/compat/string.h:78:8: error: incompatible implicit declaration of built-in function ‘malloc’ [-Werror]
/home/smarchi/src/lttng-tools/src/common/compat/string.h:78:8: note: include ‘<stdlib.h>’ or provide a declaration of ‘malloc’
Note that this is in fallback code when the system doesn't provide
strndup (or, in my case, the system provides it but configure failed to
find it).
Issue
=====
Run the following command:
lttng enable-event -k --probe "\do_fork" my_do_fork_event
currently fails and that is expected.
But it does not fail for the right reason. In the `parse_probe_opts()`
function, during the last step of parsing the probe description we assume
it's a raw address and pass the string directly to the `strtoul()`
function. So if the probe description is not an address at all (e.g.
"\do_fork"), the `strtoul()` call will return 0 in the `addr` field of
the probe struct. This is then passed to the kernel tracer that asks the
kernel to instrument that address with a kprobe. This fails because 0x0
is not an address that can be instrumented.
Solution
========
Check that the first character of the tentative address is a digit
before trying to convert the string to an integer. This is not perfect
but at least it prevents some errors.
Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Change-Id: I444f0e7694098b1cdb56ecbf5d92be8974e406dc Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: lttng: placing probe on symbol starting with `_`
Issue
=====
The lttng CLI tool does not parse `--probe` symbol name properly if the
name has an underscore at the beginning.
For example, the following command fails
lttng enable-event -k --probe _do_fork my_do_fork_event
This happens because the `parse_probe_opts()` function looks if the
first character of the symbol field is an alphabetic character to
determine if a symbol was provided. The problem is that some kernel
symbols such as `_do_fork` start with an underscore.
Solution
========
check if the first character is an alphabetic character OR an
underscore.
Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Change-Id: I3ee6c26641ceee508ee78e895d372c6b09fe90fb Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Test: rotate_utils.sh: consider chunk archive with ust/ as empty
Now the session daemon needs to create the ust/ subdir to pass it
to the consumer daemon even if there are no active traced applications
in per-pid tracing. Therefore, we need to consider a chunk with a
ust/ empty directory as empty.
Empty local traces have this empty subdir, but remote traces do not.
Honor "active" flush flag in both kernel and ust consumers. A flush
"active" does a flush which will not generate empty packets (no event),
whereas an "inactive" flush will generate empty packets if flushing
a current packet which has no event.
Fix: sessiond cmd.h: include missing lttng-sessiond.h
lttng-sessiond.h declares struct command_ctx which is used in cmd.h
prototypes.
It typically does not generate a compilation error because all
compile units including cmd.h also include lttng-sessiond.h, but
it is cleaner to include dependencies directly in cmd.h.
Fix: consumerd: use packet sequence number for rotation position
Refer to "Fix: relayd: use packet sequence number for rotation position"
for context of this change.
This commit introduces the changes required in the consumerd.
Some notable points related to this commit:
- Internally, the rotate_position (per-stream) is now a 64-bit
value rather than an unsigned long.
- The scheme to rotate a stream is changed to allow using the
backward-compatible lttng_consumer_take_snapshot() rather than
the newer lttng_consumer_get_produced_snapshot(), thus allowing
backward compatibility of the implicit rotation on destroy with
pre-2.10 lttng-modules.
- The rotate position used as pivot point for the rotation is
based on the packet_seq_num of the last packet that has been
send over the network by consumerd, incremented by the number of
packets between the sampled produced_pos and the consumed_pos.
In the worse case scenario where an overwrite mode ring buffer
overwrites its contents enough to trigger a 4GB overflow on a
32-bit producer since the last packet was sent (e.g. due to a
slow network), the difference between produced_pos and
consumed_pos will be lower that what would have been expected.
However, because this pivot position is used as a lower bound,
being smaller than the real value is fine: the data that would
have been misplaced in the wrong trace chunk were actually
overwritten, and will therefore never be consumed.
- When interacting with pre-2.8 lttng-modules, the packet sequence
number is not available. The current approach is to disallow
rotations performed on sessions which have kernel tracing active
with a pre-2.8 lttng-modules.
Fix: relayd: per-pid live: no new metadata vs close
When using lttng-live on a per-pid UST trace, the metadata stream is
closed after an application exits. The live viewer observes that the
stream has no more data when getting the metadata returns 0 bytes.
Internally in the relay daemon, it is assumed that a metadata stream
can be put (and thus removed) as soon as all the metadata has been sent
to the viewer, but this is not quite right. The viewer actually needs to
observe a 0-byte reply after receiving all the metadata in order to
gracefully perceive the metadata stream hang up.
Therefore, add a no_new_metadata_notified flag to the metadata stream
to track whether that 0-byte message has been sent to the viewer since
the last metadata content was sent, and postpone the reclamation of the
metadata stream until it is closed _and_ that 0-byte reply was sent to
the live viewer.
Fix: relayd: use packet sequence number for rotation position
The "network" sequence number (net_seq_num) is a 64-bit sequence number
tagging each packet sent over the network. The net_seq_num increments
monotonically (+1) for each packet sent from consumer daemon to relay
daemon, on a per-stream basis. It is tagged by the consumer daemon when
sending a trace packet to the relay daemon.
The LTTng kernel and user-space ring buffer "consumed position"
(consumed_pos) and "produced position" (produced_pos) are free-running
counters counting the number of bytes consumed and produced so far by
each stream. Because those counters are updated atomically, they are
limited to a size of 32-bit on 32-bit architectures.
The "packet" sequence number (packet_seq_num) is a sequence number
found in the packet header starting from LTTng 2.8. It is a 64-bit
sequence number assigned by the lttng-modules and lttng-ust ring
buffers. It increments monotonically (+1) for each packet produced
within a given ring buffer (stream).
Using produced_pos as rotation position and comparing it to the
net_seq_num has a few issues:
1) It breaks on 32-bit producers after generating more than 4GB of
data per stream, due to overflow. The net_seq_num is a 64-bit
counter, which does not overflow, but the produced_pos overflows
after 4GB on 32-bit architectures. This can lead to never-completing
rotations.
2) It breaks scenarios where ring buffers are configured in
overwrite mode, and streaming to a relay daemon. Indeed, when
the ring buffer moves the consumed_pos ahead, actually overwriting
data within the ring buffer, it introduces an offset between the
produced_pos and the net_seq_num. Therefore, if producers are
generating a low- (or no-) throughput in some streams, the
rotation may never complete, even on 64-bit architectures.
The solution proposed for this issue is to use the packet_seq_num as
rotation position rather than the net_seq_num. It takes care of
the two problematic scenarios, since the counter is always 64-bit
(even on 32-bit architectures), and because the counter is managed
by the producer, which therefore tracks progress of the ring buffer
overwrites.
This commit introduces changes required at the relayd side. A
separate commit introduces the changes required in the consumerd.
In relayd, one major restriction is the fact that the packet_seq_num
is not sent over the data socket, only through the control socket
receiving the indexes.
Therefore, in order to figure out the pivot position for the data
socket for a given stream, the associated index first needs to be
received. At that point, the corresponding net_seq_num is known,
which provides the pivot position for the data stream. Given that
the data and index sockets provide no ordering guarantees with
respect to their arrival, we handle the fact that data might have
been saved to disk in the wrong (previous) trace chunk by moving
it to the next trace chunk when the pivot position is known.
In order to allow "jumps" in the sequence numbers produced by
overwrite mode buffers, try_rotate_stream_index(), which previously
asserted that each sequence number was received in sequence, now
uses the packet_seq_num pivot position as a lower (inclusive) bound.
The lack of proper care around use of macro arguments in LTTNG_OPTIONAL_GET
allowed this code to compile, but caused the following issue (manually
replacing "optional" argument with the a
Using LTTNG_OPTIONAL_GET(&stream->ongoing_rotation)->next_trace_chunk
Fix: optional.h macro missing parentheses and guards
The are a few coding style issues with optional.h which leads to
unexpected effects when the macros are used in the caller code.
All macro parameters need to be surrounded by () (except when used near
commas, which is the C operator with least precedence).
All macros that emit code need to be surrounded by do { } while (0) so
not to emit extra ; or omit ;, which can cause subtle issues when used
with if/else statements.
Simon Marchi [Fri, 13 Dec 2019 21:47:57 +0000 (16:47 -0500)]
dynamic-array: fix documentation of lttng_dynamic_pointer_array_get_pointer
The documentation of this function says that mutating the array
invalidates the return pointer. This is not true, since the returned
pointer is the element itself, not a pointer to the array.
Change-Id: I8b8978cddb2d1d6ce0b42ed313e9843ca418c96c Signed-off-by: Simon Marchi <simon.marchi@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Jonathan Rajotte [Wed, 11 Dec 2019 20:58:58 +0000 (15:58 -0500)]
Fix: tests: metadata presence on relayd is not deterministic
There is no synchronization point guaranteeing the presence of metadata on
lttng-relayd side when the live metadata request is done. It must be
present at some point in the future but might not be at the moment we
perform the request.
Add a retry phase to this step. It must succeed in the future.
Not sure how this test was never marked as flaky.
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Change-Id: I033005c6a228013e699c74d8e8faafcb3272dd98 Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: relayd: missing metadata stream causes all traces to be skipped
Commit 123ed7c22 intends for a trace that doesn't have a metadata
stream to be skipped when creating viewer streams. However, the loop
over ctf_traces should be "continued" rather then "broken" from when
this situation arises. Otherwise, all ctf_traces of the session are
skipped, which is not the intention here.
Moreover, a reference to the current ctf_trace is leaked when the
break (now continue) occurs.
conftest.c:154: note: this is the location of the previous definition
#define CONFIG_CMD_DESCR_ROTATE "Archive a tracing session's current trace chunk"
cc1: all warnings being treated as errors
Signed-off-by: Simon Marchi <simon.marchi@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: relayd: don't send streams if there is no metadata
Issue
=====
When tracing short-live UST apps in per-pid mode, it happens that traces
are closed before we can send all the streams to the viewer. This can
place the viewer in an uncomfortable position where it is aware of data
streams of a trace but can't get the metadata stream to decode the
events.
Solution
========
Only send the data streams if we have the metadata stream or if the
metadata stream was already sent. This ensures that the viewer will
either have all the {data,metadata} streams or none of them.
Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: consumerd: assert on null trace chunk on session restart
The consumer daemon asserts on
`stream->net_seq_idx != (uint64_t) 1ULL || stream>trace_chunk'
when a session is re-started following a rotation.
Steps to reproduce, while an instrumented application is running:
$ lttng create
$ lttng enable-event -u -a
$ lttng start
$ lttng stop
$ lttng rotate
$ lttng start
-> assertion fails
The trace chunk of a stream can be null in this scenario as the
"create trace chunk" consumer command immediately sets the streams'
current trace chunk when they are transitioning from a "null" trace
chunk.
Since 1f4962443, a session restart will cause a rotation to occur from
"null" to the streams' new trace chunk. When this rotation occurs, the
channel and their streams are seen to be in the same trace chunk.
This is unexpected as this should only occur when transitioning from a
trace chunk to the "null" trace chunk (no output). In that case, the
streams are considered to have reached the point where they should
discard their current trace chunk to enter the "null trace chunk"
state (having no current output). This is exactly the opposite of
the situation here as streams are transitioning from a null to a
non-null trace chunk.
Hence, the immediate assignation of the trace chunk to the streams
should no longer be performed on creation of a trace chunk on the
consumer daemon. The streams transition from the "null" trace chunk to
a new trace chunk through the "rotate channel" command as is done for
all other rotation operations. Removing this bypass also ensures that
the rotation behaviour of both the consumer and relay daemons match.
Fix: sessiond: don't wait for a rotation from a null chunk to finish
The rotation completion checking does not handle waiting for the
completion of a rotation _from_ a NULL trace chunk. This is correct as
there is essentially nothing to check. Streams always rotate out of a
null trace chunk immediately as it means the stream had no output and
could not receive data.
Concretely, this happens when stopping a session, rotating, and
re-starting a session.
The fix consists in simply re-working the logic of the "rotate"
command to not launch a rotation completion check job and not put the
session in the "rotation ongoing" state.
Fix: sessiond: duplicated rotation notification sent
A duplicate notification that a rotation was launched and completed
is sent by the rotation thread when a rotation is performed after
a session was stopped.
This code is removed at it is a left-over from the time when the
rotation thread had to explicitly rename trace output folders
when a rotation had completed.
Fix: sessiond: no rotation performed from null chunk to new chunk
The session daemon must rotate from a null trace chunk to a new trace
chunk when a session's current trace chunk is null. This situation
happens when a session is stopped, rotated, and started again.
This bug leaves existing streams in the "null" trace chunk and causes
the relay daemon to report a protocol error on the reception of the
first data packet following such a start.
Fix: invalid use of destructor in dynamic pointer array
A dynamic pointer array is built on top of a dynamic array and uses
the dynamic array's internal "destructor" field to store the
user-specified destructor.
lttng_dynamic_pointer_array_remove_pointer currently uses
the dynamic array's remove_element directly which causes the
user destructor to be called with the underlying storage of the
pointer rather than with the pointer itself.
This change re-uses the same pattern as
lttng_dynamic_pointer_array_reset(), namely using the destructor
explicitly and setting it to NULL for the duration of the call to
the dynamic array API.
Fix: relayd: check for a trace chunk before writing a packet
Protocol errors can cause a packet to be written to a stream that
doesn't have an active trace chunk. Validate this condition for the
init and write packet operations on a stream.
Fix: relayd: viewer session trace chunk not released on detach
The 'attach' command on a viewer session expects (asserts) the trace
chunk of the viewer session to be NULL. This is reasonable as there is
no reason to hold a reference to a trace chunk while no clients are
attached.
Release the reference to the trace chunk on detach. The relay
session's trace chunk will be re-sampled (copied) when the next client
attaches to the viewer session.
Fix: relayd: session trace chunk is copied too late
In per-pid buffering mode, a viewer can attach to a session while it
is active and find it has been closed by the time it requests new
streams. The viewer session's trace chunk is created as a side-effect
of the "get_new_streams" command and can find that the relay_session's
trace chunk has now been closed, causing the creation of the viewer
session trace chunk to fail.
This results in an unexpected error being reported to the live client.
This fix moves the creation of the viewer session's trace chunk to the
"attach" command. If the creation fails, the session is reported as
being "unknown".
Reported-by: Francis Deslauriers <francis.deslauriers@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com> Tested-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Do not hold the registry lock while communicating with the consumerd,
because doing so causes inter-process deadlocks between consumerd and
sessiond with the metadata request notification.
The deadlock involves both sessiond and consumerd:
relayd: close viewer stream trace chunk earlier on release
A viewer stream puts its references to its stream and index files
within its "release" method (called when its reference count reaches
0).
However, the reference to its trace chunk is only released during the
RCU reclamation of the viewer stream. This unnecessarily delays the
clean-up of the viewer trace chunk.
For cleanliness' sake, move the release of the viewer stream's trace
chunk to the release method, just after the release of the various
file handles of that stream.
Fix: relayd: put chunk reference when closing stream
If a stream is closed by an application exiting (per-pid buffers), it
needs to put its reference on the stream trace chunk right away, because
otherwise still holding the reference on the trace chunk could allow a
viewer stream (which holds a reference to the stream) to postpone
destroy waiting for the chunk to cease to exist endlessly until the
viewer is detached.
Fix: relayd: tracefile rotation: viewer opening missing index file
Moving the head position of the tracefile array when the data is
received opens a window where a viewer attaching to the session could
try to open a missing index file (which has not been received yet).
However, we want to bump the tail position as soon as we receive
data, because the prior tail is not valid anymore.
Solve this by introducing two head positions: the "read" head
and the "write" head. The "write" head is the position of the
newest data file (equivalent to the prior "head" position). We
also introduce a "read" head position, which is only moved
forward when the index is received.
The viewer now uses the "read" head position as upper bound, which
ensures it never attempts to open a non-existing index file.
Jonathan Rajotte [Fri, 25 Oct 2019 22:12:00 +0000 (18:12 -0400)]
Fix: move set base_path of session to URI configuration
The load code still uses the "old" API to create and configure network
session output (lttng_create_session followed by
lttng_set_consumer_url). The session base_path is only set in the
cmd_create_session_from_descriptor function. This results in invalid
network output paths when using a loaded session configuration (xml).
While we might want to move the load code to the new API, there is a
case to be made in not breaking the previous API behaviour.
To restore the expected behaviour of lttng_set_consumer_url, move the
assignation of the session base_path to the cmd_set_consumer_uri
function (LTTNG_SET_CONSUMER_URI).
Both the previous and session descriptor based creation API uses this
code path when needed (network output).
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Michael Jeanson [Thu, 31 Oct 2019 20:12:46 +0000 (16:12 -0400)]
Fix: check for dtrace and sdt.h before enabling SDT uprobe tests
Add a configure switch '--enable-sdt-uprobe / --disable-sdt-uprobe', the
default behavior of enabling the test if the requirements are found is
kept but it's now possible to explicitly disable it.
Also add the detection of the dtrace binary and its override trough the
DTRACE environment variable.
Signed-off-by: Michael Jeanson <mjeanson@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: consumerd: crash occurs when taking snapshot of ust channel
Commit 8e1ef46e8 added an acquisition of the metadata_stream's lock
during consumer_metadata_cache_flushed() as stream attributes are
used. However, when this function is called, the metadata channel's
stream can already be NULL, as indicated by the function's comments.
Check if the stream is NULL before attempting to acquire its lock.
Fix: relayd: live: crash when creating viewer streams
Viewer streams can be creating while serving a "GET_STREAMS" viewer
client command for a session that is being destroyed. If this happens,
the viewer streams will be created with a NULL viewer trace chunk,
which would result in a crash.
The fix consists in returning a stream error when such a command
happens during the destruction of a session. This is the same
behaviour than if the session could not be found at all, introducing
no meaningful change in behaviour from the viewer's perspective.
Fix: relayd: live: crash on attach to a session without trace chunk
Attaching to a session that doesn't have a current trace chunk results
in a crash when the viewer streams are created from a NULL viewer
trace chunk.
Live clients are prevented from attaching to sessions without a
current trace chunk as those sessions are either being destroyed or
too young to have a trace chunk, meaning that they don't have streams
yet. Live clients will receive the "unknown" status code that they
already receive when asking an unknown session. Since such sessions
are not listed, this shouldn't change any exposed behaviour.
Fix: relayd: live: some listed sessions are not attacheable
The list sessions command currently returns sessions that do not
have a current trace chunk. This can be caused by the session
either being destroyed or being so young that it hasn't had a
trace chunk created against it yet.
In both cases, such sessions would not be attacheable in their
current condition. This fix omits them from from the listing
to reduce the number of failures at the "attach session" and
"attach stream" step.
Fix: relayd: don't put un-acquired trace chunk reference
stream_create() should not release (put) the reference to the current
trace chunk in its error path if it could not acquire a new reference
in the first place.
Fix: relayd: don't put un-acquired viewer trace chunk reference
viewer_stream_create() should not release (put) the reference to
the viewer_trace_chunk in its error path if it could not acquire
a new reference in the first place.
Fix: consumerd: NULL pointer dereference during metadata sync
The following crash was reported when short-lived applications
are traced in a live session with per-pid buffering channels.
From the original report:
```
Thread 1 (Thread 0x7f72b67fc700 (LWP 1912155)):
#0 0x00005650b3f6ccbd in commit_one_metadata_packet (stream=0x7f729c010bf0) at ust-consumer.c:2537
#1 0x00005650b3f6cf58 in lttng_ustconsumer_sync_metadata (ctx=0x5650b588ce60, metadata=0x7f729c010bf0) at ust-consumer.c:2608
#2 0x00005650b3f4dba3 in do_sync_metadata (metadata=0x7f729c010bf0, ctx=0x5650b588ce60) at consumer-stream.c:471
#3 0x00005650b3f4dd3c in consumer_stream_sync_metadata (ctx=0x5650b588ce60, session_id=0) at consumer-stream.c:548
#4 0x00005650b3f6de78 in lttng_ustconsumer_read_subbuffer (stream=0x7f729c0058e0, ctx=0x5650b588ce60) at ust-consumer.c:2917
#5 0x00005650b3f45196 in lttng_consumer_read_subbuffer (stream=0x7f729c0058e0, ctx=0x5650b588ce60) at consumer.c:3524
#6 0x00005650b3f42da7 in consumer_thread_data_poll (data=0x5650b588ce60) at consumer.c:2894
#7 0x00007f72bdc476db in start_thread (arg=0x7f72b67fc700) at pthread_create.c:463
#8 0x00007f72bd97088f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
The segfault happen on the access to 'stream->chan->metadata_cache->lock'
chan value here is zero.
```
The problem is easily reproducible if a sleep(1) is added just after
the call to lttng_ustconsumer_request_metadata(), before the metadata
stream lock is re-acquired.
During the execution of the "request_metadata", an application can
close. This will cause the session daemon to push any remaining
metadata to the consumer daemon and to close the metadata channel.
Closing the metadata channel closes the metadata stream's wait_fd,
which is an internal pipe. The closure of the metadata pipe is
detected by the metadata_poll thread, which will ensure that all
metadata has been consumed before issuing the deletion of the metadata
stream and channel.
During the deletion, the channel's "stream" attribute the stream's
"chan" attribute are set to NULL as both are logically deleted and
should not longer be used.
Meanwhile, the thread executing commit_one_metadata_packet()
re-acquires the metadata stream lock and trips on the now-NULL "chan"
member.
The fix consists in checking if the metadata stream is logically
deleted after its lock is re-acquired. It is correct for the
sync_metadata operation to then complete successfully as the metadata
is synced: the metadata guarantees this before deleting the
stream/channel.
Since the metadata stream's lifetime is protected by its lock, there
may be other sites that need such a check. The lock and deletion check
could be combined into a single consumer_stream_lock() helper in
follow-up fixes.
Reported-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
consumerd: clean-up: stream attribute accessed without locking stream
consumer_metadata_cache_flushed makes use of the metadata stream's
ust_metadata_pushed attribute without locking while it is updated by
commit_one_metadata_packet() which holds the metadata stream lock.
This is marked as a clean-up since the attribute appears to always be
accessed while the metadata cache lock is held. However this is a
_channel_ attribute and the stream and channel lifetimes do not match,
making the locking assumptions conceptually dubious.
Fix: sessiond: use system LTTng-UST headers when available
The LTTng-Tools tree includes a local copy of three LTTng-UST headers:
* ust-error.h
* ust-ctl.h
* ust-abi.h
The system headers should be used when UST support is configured to
ensure the appropriate ABI definitions are used. The local copies of
the headers should only be used when LTTng-Tools is built with the
--without-lttng-ust configuration option. Those headers are needed
since some UST support code is compiled-in even though the support
is deactivated.
A misconfiguration in the CI setup allowed us to notice that
sessiond-config.c is using the internal header unconditionally.
To ensure this doesn't happen in the future, the local copies
are renamed:
* ust-error.h -> ust-error-internal.h
* ust-ctl.h -> ust-ctl-internal.h
* ust-abi.h -> ust-abi-internal.h
All code should use the `lttng-` prefixed versions of the headers
which include either the local or "system" copy of the headers
depending on the build configuration.
Philippe Proulx [Fri, 18 Oct 2019 19:53:05 +0000 (15:53 -0400)]
doc/man: use specific revision date for each manual page
This patch makes each manual page indicate its own revision date with
the `revdate` AsciiDoc attribute.
In `asciidoc.conf`, we use this attribute to specify the DocBook
reference page date (see
<https://tdg.docbook.org/tdg/4.5/refentryinfo.html> and
<https://tdg.docbook.org/tdg/4.5/date.html>).
Without the DocBook date tag, `xmlto` uses the current date. You can
see this date at the bottom of the rendered manual page:
...
SEE ALSO
lttng-enable-rotation(1), lttng-disable-rotation(1), lttng(1)
LTTng 2.12.0-pre 10/18/2019 LTTNG-ROTATE(1)
Using the manual page generation date seems unexpected for the reader
here.
For this initial change, I used the last commit date for each source
file.
Signed-off-by: Philippe Proulx <eeppeliteloop@gmail.com> Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Fix: sessiond: unbalanced health register/unregister on error
A number of threads do not correctly pair registrations and
unregistrations to the health monitoring subsystem when an error
forces them to abort early. Since the pattern is mostly the same
in the notification and rotation thread, they are both fixed in
the same commit.
Fix: sessiond: leak of trace chunk on destruction error
By design, a trace chunk can be leaked on the consumer daemon's end if
the session daemon does not close it. This is because the consumer
daemon has no "top-level" session object which could bound the
lifetime of a trace chunk.
It was reported that errors during a session destruction operation
could result in a trace chunk leak being reported by the consumer
daemon on shut down.
In the case that was reported, the failure to launch an application
caused the metadata channel to never be created. When the session was
destroyed, the rotation of the metadata channel failed with a "channel
does not exist" error. This error caused cmd_rotate_session() to abort
before the trace chunk close command was sent to the consumer
daemon(s). This ultimately results in the leak described earlier.
The fix consists in performing the trace chunk close command on the
consumer daemon even if the rotation itself fails.
While there is a good chance that mkdir is the actual syscall that
fails when this error code is returned, the error messages should
describe the operation that failed and not its implementation.
Fix: sessiond: session destruction errors are unreported
The session daemon does not report errors which occur while setting-up
a session's destruction. For instance, if the implicit rotation or
rotation to the "null" chunk fails. While the session will be
destroyed (it will no longer appear in session listings), the session
daemon could have failed to destroy it properly and it could be
corrupted/unreadable.
This reports those errors so the user does not expect the session to
be readable (but it _could_ be).
This was discovered while investigating another, unrelated, issue.
projects / lttng-tools.git / log
