lttng-tools.git
2 years agoFix: test: lttng kernel modules still loaded after running test_clock_override
Jonathan Rajotte [Fri, 25 Mar 2022 18:26:38 +0000 (14:26 -0400)] 
Fix: test: lttng kernel modules still loaded after running test_clock_override

Observed issue
==============

After running test_clock_override, some lttng modules are still loaded.

$ lsmod | ag lttng
  lttng_test             32768  0
  lttng_tracer         2326528  1 lttng_test
  lttng_statedump       749568  1 lttng_tracer
  lttng_wrapper          16384  2 lttng_statedump,lttng_tracer
  lttng_uprobes          16384  1 lttng_tracer
  lttng_kprobes          16384  1 lttng_tracer
  lttng_lib_ring_buffer    61440  1 lttng_tracer
  lttng_kretprobes       16384  1 lttng_tracer
  lttng_clock_plugin_test    16384  1
  lttng_clock            16384  2 lttng_tracer,lttng_clock_plugin_test

Cause
=====

The order in which the modules are removed is important.

In `test_clock_override_timestamp` the last `modprobe --remove order` is

  modprobe --remove lttng-clock-plugin-test lttng-clock lttng-test

While other callsites order is:

  modprobe --remove lttng-test lttng-clock-plugin-test lttng-clock

Solution
========

Use

  modprobe --remove lttng-test lttng-clock-plugin-test lttng-clock

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I528df2e3e90664433337a547a74cdbe476d4ee62

2 years agoUpdate version to v2.13.7 v2.13.7
Jérémie Galarneau [Wed, 13 Apr 2022 18:27:57 +0000 (14:27 -0400)] 
Update version to v2.13.7

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: sessiond: assert on empty payload when handling client out event
Jérémie Galarneau [Fri, 8 Apr 2022 23:34:04 +0000 (19:34 -0400)] 
Fix: sessiond: assert on empty payload when handling client out event

Observed issue
==============

When servicing a large number of tracer notifications and sending
notifications to clients, the session daemon occasionally hits
an assertion:

  #4  0x00007fb224d7d116 in __assert_fail () from /usr/lib/libc.so.6
  #5  0x000056038b2fe4d7 in client_flush_outgoing_queue (client=0x7fb21400c3b0) at notification-thread-events.cpp:3586
  #6  0x000056038b2ff819 in handle_notification_thread_client_out (state=0x7fb221974090, socket=77) at notification-thread-events.cpp:4104
  #7  0x000056038b2f3d77 in thread_notification (data=0x56038cc7fe90) at notification-thread.cpp:763
  #8  0x000056038b30ca7d in launch_thread (data=0x56038cc7e220) at thread.cpp:66
  #9  0x00007fb224dcf5c2 in start_thread () from /usr/lib/libc.so.6
  #10 0x00007fb224e54584 in clone () from /usr/lib/libc.so.6

Cause
=====

A client "out" event can be received when no payload is left
to send under some circumstances.

Many threads can flush a client's outgoing queue and, if they
had to queue their message (socket was full), will use the
"communication update" command to signal the (e)poll thread
to monitor for space being made available in the socket.

Commands are sent over an internal pipe serviced by the same
thread as the client sockets.

When space is made available in the socket, there is a race
between the (e)poll thread and the other threads that may
wish to use the client's socket to flush its outgoing queue.

A non-(e)poll thread may attempt (and succeed) in flushing
the queue before the (e)poll thread gets a chance to service
the client's "out" event.

In this situation, the (e)poll thread processing the client
out event will see an empty payload: there is nothing to do.

Solution
========

The (e)poll thread can simply ignore the "client out" event
when an empty payload is seen.

There is also no need to update the transmission status as
the other thread has already enqueued a "communication
update" command to do so.

Known drawbacks
===============

None.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I8a181bea1e37e8e14cc67b624b76d139b488eded

2 years agoFix: Revert of 814b4934e2604a419bcb8eec57c0450dbb47e2c3
Jonathan Rajotte [Wed, 6 Apr 2022 13:17:38 +0000 (09:17 -0400)] 
Fix: Revert of 814b4934e2604a419bcb8eec57c0450dbb47e2c3

Observed issue
==============

During high throughput event notification generation scenarios the
following deadlock happens:

 Thread 14 (Thread 0x7f74b4ff9700 (LWP 76062)):
 #0  __lll_lock_wait (futex=futex@entry=0x56408765dde8, private=0) at lowlevellock.c:52
 #1  0x00007f74c941a0a3 in __GI___pthread_mutex_lock (mutex=0x56408765dde8) at ../nptl/pthread_mutex_lock.c:80
 #2  0x000056408704b207 in run_command_wait (handle=0x56408765ddd0, cmd=0x7f74b4ff7f70) at notification-thread-commands.cpp:31
 #3  0x000056408704bcef in notification_thread_command_remove_tracer_event_source (handle=0x56408765ddd0, tracer_event_source_fd=54) at notification-thread-commands.cpp:319
 #4  0x000056408708a0c1 in delete_ust_app (app=0x7f749c000bf0) at ust-app.cpp:1059
 #5  0x000056408708a511 in delete_ust_app_rcu (head=0x7f749c000ca0) at ust-app.cpp:1122
 #6  0x00007f74c988b4a7 in call_rcu_thread (arg=0x7f74b8004a80) at ../src/urcu-call-rcu-impl.h:369
 #7  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #8  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 13 (Thread 0x7f74b57fa700 (LWP 76047)):
 #0  0x00007f74c933a49e in epoll_wait (epfd=48, events=0x7f74a4000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b57f9240, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x00005640870abb65 in thread_agent_management (data=0x56408765f0b0) at agent-thread.cpp:424
 #3  0x0000564087062b1a in launch_thread (data=0x56408765f150) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 12 (Thread 0x7f74b5ffb700 (LWP 76046)):                                                                                                                                       [630/709]
 #0  0x00007f74c933a49e in epoll_wait (epfd=47, events=0x7f74a0000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b5ffa170, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x00005640870a4095 in thread_application_notification (data=0x56408765ee40) at notify-apps.cpp:78
 #3  0x0000564087062b1a in launch_thread (data=0x56408765eed0) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 11 (Thread 0x7f74b67fc700 (LWP 76045)):
 #0  0x00007f74c933a49e in epoll_wait (epfd=44, events=0x7f74ac000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b67fb170, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x00005640870723db in thread_application_management (data=0x56408765ebd0) at manage-apps.cpp:93
 #3  0x0000564087062b1a in launch_thread (data=0x56408765ec60) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 10 (Thread 0x7f74b6ffd700 (LWP 76044)):
 #0  0x00007f74c933a49e in epoll_wait (epfd=39, events=0x7f74a8000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b6ffc130, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x0000564087070a27 in thread_application_registration (data=0x56408765e940) at register.cpp:214
 #3  0x0000564087062b1a in launch_thread (data=0x56408765e9f0) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 9 (Thread 0x7f74b77fe700 (LWP 76043)):                                                                                                                                        [654/709]
 #0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
 #1  0x00005640870c8e25 in futex (uaddr=0x5640871e2800 <ust_cmd_queue>, op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at /home/joraj/lttng/master/install/include/urcu/futex.h:72
 #2  0x00005640870c8e6d in futex_async (uaddr=0x5640871e2800 <ust_cmd_queue>, op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at /home/joraj/lttng/master/install/include/urcu/futex.h:104
 #3  0x00005640870c939a in futex_nto1_wait (futex=0x5640871e2800 <ust_cmd_queue>) at futex.cpp:77
 #4  0x000056408706f2af in thread_dispatch_ust_registration (data=0x56408765e740) at dispatch.cpp:453
 #5  0x0000564087062b1a in launch_thread (data=0x56408765e760) at thread.cpp:66
 #6  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #7  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 8 (Thread 0x7f74b7fff700 (LWP 76042)):
 #0  0x00007f74c933a49e in epoll_wait (epfd=33, events=0x7f74b0000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74b7ffad40, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x000056408706c424 in thread_manage_clients (data=0x56408765e4f0) at client.cpp:2528
 #3  0x0000564087062b1a in launch_thread (data=0x56408765e560) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 7 (Thread 0x7f74c4b8f700 (LWP 76041)):                                                                                                                                        [672/709]
 #0  0x00007f74c933a49e in epoll_wait (epfd=31, events=0x7f74bc000b60, maxevents=3, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74c4b8e240, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x000056408705f2b6 in thread_rotation (data=0x56408765e280) at rotation-thread.cpp:804
 #3  0x0000564087062b1a in launch_thread (data=0x56408765e310) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 6 (Thread 0x7f74c5390700 (LWP 76040)):
 #0  0x00007f74c925f1d2 in __GI___sigtimedwait (set=0x7f74c538f090, info=0x7f74c538f110, timeout=0x0) at ../sysdeps/unix/sysv/linux/sigtimedwait.c:29
 #1  0x000056408706138a in thread_timer (data=0x7ffc1fcbe3f0) at timer.cpp:359
 #2  0x0000564087062b1a in launch_thread (data=0x56408765e0a0) at thread.cpp:66
 #3  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #4  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 5 (Thread 0x7f74c5b91700 (LWP 76039)):
 #0  __libc_write (nbytes=8, buf=0x7f74c5b8fc88, fd=24) at ../sysdeps/unix/sysv/linux/write.c:26
 #1  __libc_write (fd=24, buf=0x7f74c5b8fc88, nbytes=8) at ../sysdeps/unix/sysv/linux/write.c:24
 #2  0x00005640870eeb4f in lttng_write (fd=24, buf=0x7f74c5b8fc88, count=8) at readwrite.cpp:77
 #3  0x000056408704b535 in run_command_no_wait (handle=0x56408765ddd0, in_cmd=0x7f74c5b8fdf0) at notification-thread-commands.cpp:92
 #4  0x000056408704bf49 in notification_thread_client_communication_update (handle=0x56408765ddd0, id=2, transmission_status=CLIENT_TRANSMISSION_STATUS_QUEUED) at notification-thread-command
 #5  0x000056408707bc62 in client_handle_transmission_status (client=0x7f74b80050d0, status=CLIENT_TRANSMISSION_STATUS_QUEUED, user_data=0x7f74b8004410) at action-executor.cpp:258
 #6  0x0000564087057525 in notification_client_list_send_evaluation (client_list=0x7f74b8004df0, trigger=0x7f74b0001030, evaluation=0x7f74b815d1d0, source_object_creds=0x0, client_report=0x5
 #7  0x000056408707bce9 in action_executor_notify_handler (executor=0x7f74b8004410, work_item=0x7f74b815d430, item=0x7f74b80e48e0) at action-executor.cpp:269
 #8  0x000056408707dd6d in action_executor_generic_handler (executor=0x7f74b8004410, work_item=0x7f74b815d430, item=0x7f74b80e48e0) at action-executor.cpp:670
 #9  0x000056408707df01 in action_work_item_execute (executor=0x7f74b8004410, work_item=0x7f74b815d430) at action-executor.cpp:689

 #10 0x000056408707e525 in action_executor_thread (_data=0x7f74b8004410) at action-executor.cpp:771                                                                                   [698/709]
 #11 0x0000564087062b1a in launch_thread (data=0x7f74b80044b0) at thread.cpp:66
 #12 0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #13 0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 4 (Thread 0x7f74c6392700 (LWP 76038)):
 #0  __lll_lock_wait (futex=futex@entry=0x56408765dde8, private=0) at lowlevellock.c:52
 #1  0x00007f74c941a0a3 in __GI___pthread_mutex_lock (mutex=0x56408765dde8) at ../nptl/pthread_mutex_lock.c:80
 #2  0x0000564087053c89 in handle_notification_thread_command (handle=0x56408765ddd0, state=0x7f74c63911b0) at notification-thread-events.cpp:3142
 #3  0x000056408704ac81 in thread_notification (data=0x56408765ddd0) at notification-thread.cpp:715
 #4  0x0000564087062b1a in launch_thread (data=0x56408765dec0) at thread.cpp:66
 #5  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #run_command_no_wait6  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 3 (Thread 0x7f74c6b93700 (LWP 76037)):
 #0  0x00007f74c933a49e in epoll_wait (epfd=21, events=0x7f74c0000b60, maxevents=2, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7f74c6b92170, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x000056408706400a in thread_manage_health (data=0x56408765db50) at health.cpp:140
 #3  0x0000564087062b1a in launch_thread (data=0x56408765dbf0) at thread.cpp:66
 #4  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #5  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 2 (Thread 0x7f74c7394700 (LWP 76036)):
 #0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
 #1  0x00007f74c987d238 in futex (uaddr=0x564087659b10, op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at ../include/urcu/futex.h:72
 #2  futex_async (uaddr=0x564087659b10, op=0, val=-1, timeout=0x0, uaddr2=0x0, val3=0) at ../include/urcu/futex.h:104
 #3  futex_wait (futex=0x564087659b10) at workqueue.c:136
 #4  0x00007f74c987ced2 in workqueue_thread (arg=0x564087659ad0) at workqueue.c:237
 #5  0x00007f74c9417609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #6  0x00007f74c933a163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

 Thread 1 (Thread 0x7f74c73cd300 (LWP 76034)):
 #0  0x00007f74c933a49e in epoll_wait (epfd=50, events=0x564087666880, maxevents=1, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
 #1  0x00005640870eafa6 in compat_epoll_wait (events=0x7ffc1fcbe280, timeout=-1, interruptible=false) at compat/poll.cpp:280
 #2  0x0000564087062244 in sessiond_wait_for_quit_pipe (timeout_ms=-1) at thread-utils.cpp:83
 #3  0x00005640870127dc in main (argc=1, argv=0x7ffc1fcbe668) at main.cpp:1921

Cause
=====

The event_pipe used to notify the notification poll loop is full and the
lttng_write call blocks with the locks for both the client and the
cmd_queue held.

Solution
========

Go back to using eventfd but without the use of EFD_SEMAPHORE (linux
2.6.30) to continue supporting kernel between 2.6.27 and 2.6.29.

The EFD_SEMAPHORE is emulated with a read, decrement, write as explained
by the initial committer of EFD_SEMAPHORE [1].

Known drawbacks
=========

This does not solve the actual block+lock problem but simply push it
back further. The lttng_write on the eventfd can block when reaching
UINT64_MAX. This would represent, at 1 command queued per ns (which is
ridiculous), ~584 years of queueing without a dequeue operation.

Reference
=======
[1] https://lwn.net/Articles/318151/

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ie749c4169708f57463fe3cfab2366f1015bae4e0

2 years agoFix: sessiond: inverted condition checking for empty hash table
Jérémie Galarneau [Wed, 6 Apr 2022 17:37:16 +0000 (13:37 -0400)] 
Fix: sessiond: inverted condition checking for empty hash table

I inverted a condition while reformating 2a6ebf6bd. This reverts the
condition to the intention of the original author. Mea culpa.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I8c39a89f430dbb4a0f1e385b3b8e4788f188a468

2 years agoFix: notification: kernel: consumption of event notification stalls
Jonathan Rajotte [Fri, 1 Apr 2022 12:41:17 +0000 (08:41 -0400)] 
Fix: notification: kernel: consumption of event notification stalls

Observed issue
==============

Using:

 lttng add-trigger --condition event-rule-matches --type kernel:tracepoint --name "sched_waking" --capture comm --action notify

The sessiond receives multiple event notifications from the kernel event
source then stop receiving despite the kernel event source buffer
being full.

Cause
=====

It turns out that the kernel event source, when reaching near the end of
its buffer capacity, raises the POLLPRI [1] flag and not the POLLIN
flag.

Solution
========

lttng-modules stretches a bit the usage of POLLPRI as defined by the man
page (man 2 poll):

 There is some exceptional condition on the  file  descriptor. Possibilities
 include:

 *  There is out-of-band data on a TCP socket (see tcp(7)).

 *  A  pseudoterminal  master  in  packet  mode has seen a state change on the
    slave (see ioctl_tty(2)).

 *  A cgroup.events file has been modified (see cgroups(7)).

Still, even if lttng-modules changes how it does things, lttng-tools
needs to support other lttng-modules versions.

Thus, add LPOLLPRI (EPOLLPRI/POLLPRI) to the event mask when dealing
with notification event sources.

Note
=====

In the future, during the poll loop we could also prioritize
event sources in POLLPRI 'state'.

Known drawbacks
=========

None.

References
==========

[1] https://github.com/lttng/lttng-modules/blob/c312bda00d2dc10ce5f6c1189acbefee5c6c8c6c/src/lttng-abi.c#L1169

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ieb428ef1037c8eb197b489a38a1ae5216ac63d4b

2 years agoFix: notification: assert on len > 0 for dropped notification message
Jonathan Rajotte [Thu, 31 Mar 2022 13:46:15 +0000 (09:46 -0400)] 
Fix: notification: assert on len > 0 for dropped notification message

Observed issue
==============

Using the notification client from
doc/examples/trigger-condition-event-matches/notification-client.cpp, an
assert is hit when the notification subsystem is under load.

 #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 #1  0x00007f69eab58859 in __GI_abort () at abort.c:79
 #2  0x00007f69eab58729 in __assert_fail_base (fmt=0x7f69eacee588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x7f69eae1d5dd "len > 0", file=0x7f69eae1d5cb "unix.cpp", line=179, function=<optimized out>) at assert.c:92
 #3  0x00007f69eab6a006 in __GI___assert_fail (assertion=0x7f69eae1d5dd "len > 0", file=0x7f69eae1d5cb "unix.cpp", line=179, function=0x7f69eae1d598 "ssize_t lttcomm_recv_unix_sock(int, void*, size_t)") at assert.c:101
 #4  0x00007f69eadd5fe6 in lttcomm_recv_unix_sock (sock=3, buf=0x55da9ecd5f89, len=0) at unix.cpp:179
 #5  0x00007f69ead7df3f in receive_message (channel=0x55da9ecd6ee0) at channel.cpp:64
 #6  0x00007f69ead7e478 in lttng_notification_channel_get_next_notification (channel=0x55da9ecd6ee0, _notification=0x7ffdefed2570) at channel.cpp:279
 #7  0x000055da9e0e742f in main (argc=2, argv=0x7ffdefed2698) at notification-client.cpp:506

 (gdb) frame
 #5  0x00007f69ead7df3f in receive_message (channel=0x55da9ecd6ee0) at channel.cpp:64
 64              ret = lttcomm_recv_unix_sock(channel->socket,

 (gdb) print msg
 $2 = {type = 5 '\005', size = 0, fds = 0, payload = 0x7ffdefed24a8 ""}

The msg type 5 is
`LTTNG_NOTIFICATION_CHANNEL_MESSAGE_TYPE_NOTIFICATION_DROPPED`

Cause
=====

The msg portion of a
`LTTNG_NOTIFICATION_CHANNEL_MESSAGE_TYPE_NOTIFICATION_DROPPED` is indeed
zero. There is no extra payload.

Solution
========

When the msg size is zero, skip the 'payload' reception phase.

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: Ibabb922d0e410c9902414a5eabbe04738861d772

2 years agoFix: example: print_notification is called on status all returned status
Jonathan Rajotte [Thu, 31 Mar 2022 13:44:24 +0000 (09:44 -0400)] 
Fix: example: print_notification is called on status all returned status

The notification should only be printed for
`LTTNG_NOTIFICATION_CHANNEL_STATUS_OK`.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I5534406d8fbd5c0fff7013fda6335d54bef071a2

2 years agoFix: sessiond: assertion hit in ltt_sessions_ht_empty
Jonathan Rajotte [Mon, 28 Mar 2022 20:49:17 +0000 (16:49 -0400)] 
Fix: sessiond: assertion hit in ltt_sessions_ht_empty

Observed issue
==============

Scenario:

gdb lttng-sessiond
  set non-stop
  break rotation-thread.cpp:584
  ^ simulates a slow rotation thread or not scheduled thread.

lttng create test1
lttng enable-event -u -a
lttng start test1
lttng create test2
lttng enable-event -u -a
lttng start test2
lttng destroy test1
   This will hang on rotation pending checks on the CLI side.

In another shell:

lttng destroy test2
   This will hang on rotation pending checks on the CLI side.

Back to gdb
   thread 7
   continue

Results in:

 #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 #1  0x00007ffff786c859 in __GI_abort () at abort.c:79
 #2  0x00007ffff786c729 in __assert_fail_base (fmt=0x7ffff7a02588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5555556bb148 "count == lttng_ht_get_count(ltt_sessions_ht_by_name)", file=0x5555556bae9f "session.cpp", line=395, function=<optimized out>) at assert.c:92
 #3  0x00007ffff787e006 in __GI___assert_fail (assertion=0x5555556bb148 "count == lttng_ht_get_count(ltt_sessions_ht_by_name)", file=0x5555556bae9f "session.cpp", line=395, function=0x5555556bb129 "int ltt_sessions_ht_empty()") at assert.c:101
 #4  0x0000555555586d59 in ltt_sessions_ht_empty () at session.cpp:395
 #5  0x0000555555586e53 in del_session_ht (ls=0x7fffdc000c30) at session.cpp:418
 #6  0x0000555555588a95 in session_release (ref=0x7fffdc001e50) at session.cpp:999
 #7  0x000055555558620f in urcu_ref_put (ref=0x7fffdc001e50, release=0x5555555886eb <session_release(urcu_ref*)>) at /home/joraj/lttng/master/install/include/urcu/ref.h:68
 #8  0x0000555555588c8f in session_put (session=0x7fffdc000c30) at session.cpp:1048
 #9  0x00005555555bf995 in handle_job_queue (handle=0x55555575d260, state=0x7fffeeffc240, queue=0x555555758960) at rotation-thread.cpp:612
 #10 0x00005555555c05da in thread_rotation (data=0x55555575d260) at rotation-thread.cpp:847
 #11 0x00005555555c3b1c in launch_thread (data=0x55555575d2f0) at thread.cpp:66
 #12 0x00007ffff7a46609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 #13 0x00007ffff7969163 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Other scenarios can lead to a similar backtrace when using the
`--no-wait` lttng destroy option.

Cause
=====

Since ed41e5709047ef545aa28082416e641e003b45e0 [1], hash table removal
for the session object for the `ltt_sessions_ht_by_name` and
`ltt_sessions_ht_by_name` are "decoupled". Removal from
`ltt_sessions_ht_by_name` is done early in `session_destroy()` while
removal from `ltt_sessions_ht_by_id` is done during `session_release` when
the last reference of a session object is released.

This can leads to `imbalances` between the size of the two hash tables
when multiple sessions are at play.

Solution
========

Rework `ltt_sessions_ht_empty()` to exit early when
`ltt_sessions_ht_by_id` is not empty. Perform a sanity check on
`ltt_sessions_ht_by_name` only when `ltt_sessions_ht_by_id` is empty.

Note
========

Ideally both hash tables' lifetime would be managed separately but it
seems easier in term of initialization to bundle them together for now
considering the limited scope of the `ltt_sessions_ht_by_name` hash
table.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I66c459f80298f929add703ac977cccd1da6dd556

2 years agoFix: tests: missing _GNU_SOURCE for F_GETPIPE_SZ
Jonathan Rajotte [Thu, 31 Mar 2022 15:20:01 +0000 (11:20 -0400)] 
Fix: tests: missing _GNU_SOURCE for F_GETPIPE_SZ

Per man 2 fcntl:

  F_GETOWN_EX,  F_SETOWN_EX,  F_SETPIPE_SZ,  F_GETPIPE_SZ,  F_GETSIG,  F_SETSIG,
  F_NOTIFY,   F_GETLEASE,   and  F_SETLEASE  are  Linux-specific.   (Define  the
  _GNU_SOURCE macro to obtain these definitions.)

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I2b61dfb79ffa384dc2bab56cd3510ddc6ae21e85

2 years agoFix: compat: 'LTTNG_UST_ABI_PROCNAME_LEN' is undeclared
Jonathan Rajotte [Tue, 29 Mar 2022 20:31:44 +0000 (16:31 -0400)] 
Fix: compat: 'LTTNG_UST_ABI_PROCNAME_LEN' is undeclared

Observed issue
==============

On old systems, the `lttng_pthread_setname_np` function fallsback to
using the compat prctl version. In that context,
`LTTNG_UST_ABI_PROCNAME_LEN` is indeed not declared.

Solution
========

Use `LTTNG_PTHREAD_NAMELEN`. This mimics what is done in other versions
of `lttng_pthread_setname_np`.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I73956cacd7b1e9400881b17b1cd89db2530d3a00

2 years agoFix: sessiond: cmd_enable_channel: negative error code used
Jérémie Galarneau [Fri, 25 Mar 2022 19:34:47 +0000 (15:34 -0400)] 
Fix: sessiond: cmd_enable_channel: negative error code used

A negative `lttng_error_code` value is returned (as an integer)
when a channel copy fails. Return a positive error code.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I340f739cc33858a06832bb75a7a6d5e18459551f

2 years agoUpdate version to v2.13.6 v2.13.6
Jérémie Galarneau [Tue, 29 Mar 2022 01:52:30 +0000 (21:52 -0400)] 
Update version to v2.13.6

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: hide symbols erroneously exported in 2.13.5
Michael Jeanson [Mon, 28 Mar 2022 22:25:14 +0000 (18:25 -0400)] 
Fix: hide symbols erroneously exported in 2.13.5

Change-Id: I508ac4791749240e511ef832a97e92878dd68df2
Signed-off-by: Michael Jeanson <mjeanson@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoUpdate version to v2.13.5 v2.13.5
Jérémie Galarneau [Mon, 28 Mar 2022 16:11:03 +0000 (12:11 -0400)] 
Update version to v2.13.5

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: doc: action: wrong function documented for action_list destroy
Jonathan Rajotte [Thu, 24 Mar 2022 20:05:20 +0000 (16:05 -0400)] 
Fix: doc: action: wrong function documented for action_list destroy

The lttng_action_list_destroy function is internal.

API users must use `lttng_action_destroy()` to destroy the returned
object of `lttng_action_list_create()`.

Change-Id: Ic910efd07dd071f7e38e48d34a5e000b3f805729
Reported-by: Michael Jeason <mjeanson@efficios.com>
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: lttng-elf: wrong error label used by error path
Jérémie Galarneau [Fri, 18 Mar 2022 14:58:03 +0000 (10:58 -0400)] 
Fix: lttng-elf: wrong error label used by error path

1486805 Resource leak
The system resource will not be reclaimed and reused, reducing the future availability of the resource.

In lttng_elf_get_symbol_offset: Leak of memory or pointers to system resources (CWE-404)

Reported-by: Coverity Scan
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I78b868773b389c2eaf3f1d45151fe9416b1fe447

2 years agoFix: use the correct endian compat macros
Michael Jeanson [Wed, 16 Mar 2022 15:40:52 +0000 (11:40 -0400)] 
Fix: use the correct endian compat macros

Document which variant of the endian macros our compat header guarantees
across all platforms and fix incorrect uses.

This was discovered with -Wundef on macOS.

Change-Id: Iaf442fe5887063661273ac2a00c9fa4015e83d5c
Signed-off-by: Michael Jeanson <mjeanson@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: tests: uninitialized lttng_payload
Jérémie Galarneau [Wed, 16 Mar 2022 21:39:07 +0000 (17:39 -0400)] 
Fix: tests: uninitialized lttng_payload

1474980 Uninitialized pointer read
Incorrect values could be read from, or even written to, an arbitrary memory location, causing incorrect computations.

In test_event_rule_userspace_probe(): Reads an uninitialized pointer or its target (CWE-457)

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I7645278f18e4a4678fb5ede9523d0cfa8d3aa106

2 years agoFix: sessiond: ust-app: uninitialized name logged on stream copy failure
Jérémie Galarneau [Wed, 16 Mar 2022 21:35:43 +0000 (17:35 -0400)] 
Fix: sessiond: ust-app: uninitialized name logged on stream copy failure

1466302 Uninitialized scalar variable
The variable will contain an arbitrary value left from earlier computations.

In send_channel_uid_to_ust(buffer_reg_channel *, ust_app *, ust_app_session *, ust_app_channel *): Use of an uninitialized variable (CWE-457)

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Icd38de3b67dab783fa26a721c68c48ebfbb59785

2 years agoFix: lttng-elf: untrusted entry size divisor
Jérémie Galarneau [Wed, 16 Mar 2022 21:29:11 +0000 (17:29 -0400)] 
Fix: lttng-elf: untrusted entry size divisor

1405557 Untrusted divisor
The divisor could be controlled by an attacker, who could cause a division by zero.

In lttng_elf_get_symbol_offset: An unscrutinized value from an untrusted source used as a divisor (CWE-369)

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I029708a0df4f62fe0031e374d50839c26f4f3f4b

2 years agoFix: event: erroneous bound check on perf counter name size
Jérémie Galarneau [Wed, 16 Mar 2022 15:56:21 +0000 (11:56 -0400)] 
Fix: event: erroneous bound check on perf counter name size

The wrong size if used when initializing a perf counter name from a
payload. The destination size must be used to prevent out of bound
writes.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I8ea41d30815bd2c02bb2ad8b01e8cecd2d6549a8

2 years agoFix: sessiond: event name length check is too strict
Jérémie Galarneau [Wed, 16 Mar 2022 15:55:08 +0000 (11:55 -0400)] 
Fix: sessiond: event name length check is too strict

A truncation check when initializing an event from an event rule limits
the name to one less character than is supposed to be allowed.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I172c5098597923d14508c150c7b3577f759bae72

2 years agoFix: relayd: missing session unlock on error path
Jérémie Galarneau [Wed, 16 Mar 2022 14:48:59 +0000 (10:48 -0400)] 
Fix: relayd: missing session unlock on error path

1475890 Missing unlock May result in deadlock if there is another
attempt to acquire the lock.

In viewer_get_new_streams(relay_connection *): Missing a release of a
lock on a path (CWE-667)

Reported-by: Coverity Scan
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I66de344f5f39ac85bf8db93cf39a07d0c6cf7694

2 years agofix: warning '-Wstringop-truncation' with GCC 11.2
Michael Jeanson [Mon, 7 Mar 2022 16:37:49 +0000 (11:37 -0500)] 
fix: warning '-Wstringop-truncation' with GCC 11.2

Building with GCC 11.2 results in the following warning :

  In file included from ../../src/common/tracker.h:18,
                 from ../../src/bin/lttng-sessiond/trace-ust.h:17,
                 from test_ust_data.cpp:19:
../../src/common/sessiond-comm/sessiond-comm.h:569:14: note: while referencing ‘lttng_event_exclusion::names’
  569 |         char names[0][LTTNG_SYMBOL_NAME_LEN];
      |              ^~~~~
test_ust_data.cpp:209:16: warning: ‘char* strncpy(char*, const char*, size_t)’ specified bound 256 equals destination size [-Wstringop-truncation]
  209 |         strncpy(LTTNG_EVENT_EXCLUSION_NAME_AT(exclusion, 0),
      |         ~~~~~~~^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  210 |                 get_random_string(), LTTNG_SYMBOL_NAME_LEN);
      |                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
test_ust_data.cpp:211:16: warning: ‘char* strncpy(char*, const char*, size_t)’ specified bound 256 equals destination size [-Wstringop-truncation]
  211 |         strncpy(LTTNG_EVENT_EXCLUSION_NAME_AT(exclusion, 1),
      |         ~~~~~~~^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
  212 |                 get_random_string(), LTTNG_SYMBOL_NAME_LEN);
      |                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Change-Id: I78eea760b4684227ee457c3368c6397d0a767af5
Signed-off-by: Michael Jeanson <mjeanson@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoAdd Log4j 2.x agent tests for the 'log4j' domain
Michael Jeanson [Fri, 11 Feb 2022 15:26:02 +0000 (15:26 +0000)] 
Add Log4j 2.x agent tests for the 'log4j' domain

Add integration tests for the new Log4j 2.x agent in Log4j 1.x compat
mode using the current 'log4j' domain, use the new configure switch
'--enable-test-java-agent-log4j2' to enable it.

To run only this new test, use this command :

  cd tests/regression && make check TESTS="ust/java-log4j2/test_agent_log4j2_domain_log4j"

Change-Id: Id780c9ee13913c91c18548f58b14cc600e77e9fa
Depends-on: lttng-ust: I7fd5f79ad58c77175714bd4198d8ff5db2e6b846
Signed-off-by: Michael Jeanson <mjeanson@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: relayd: session id is ignored by 2.11+ create session command
Jérémie Galarneau [Thu, 10 Mar 2022 22:46:31 +0000 (17:46 -0500)] 
Fix: relayd: session id is ignored by 2.11+ create session command

The id of the session used by the sessiond is not returned by
cmd_create_session_2_11 and its caller sets the value in the
relay_session to an uninitialized value.

Up until recently this didn't have much effect as this uninitialized
value was stored and used to perform look-ups in the trace chunk
registry, which would work.

However, the recent multi-consumer rotation fixes make this problem more
significant as this 'id' is used as a key to join relay sessions
originating from the same session daemon.

This was discovered by enabling the '-Wunused-parameter' warning.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I7e33f5f93dc46bb630c431408c9472be3a75c030

2 years agoBuild fix: consumer: aggregate initialization isn't supported
Jérémie Galarneau [Wed, 9 Mar 2022 12:56:47 +0000 (07:56 -0500)] 
Build fix: consumer: aggregate initialization isn't supported

Aggregate initialization is not supported in C. Change the syntax to use
a compound literal.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I630ca41b13ea730e699e53ae9a23bdd78acbed57

2 years agoFix: consumerd: use-after-free of metadata bucket
Jérémie Galarneau [Thu, 3 Mar 2022 00:27:31 +0000 (19:27 -0500)] 
Fix: consumerd: use-after-free of metadata bucket

Observed issue
==============

When consumer_stream_destroy() is called from, for example, the error
path in setup_metadata(), consumer_stream_free() can end up being called
twice on the same stream.  Since the stream->metadata_bucket is not set
to NULL after being destroyed, it leads to a use-after-free:

 ERROR: AddressSanitizer: heap-use-after-free on address 0x604000000318
 READ of size 8 at 0x604000000318 thread T7
     #0 in metadata_bucket_destroy
     #1 in consumer_stream_free
     #2 in consumer_stream_destroy
     #3 in setup_metadata
     #4 in lttng_ustconsumer_recv_cmd
     #5 in lttng_consumer_recv_cmd
     #6 in consumer_thread_sessiond_poll
     #7 in start_thread nptl/pthread_create.c:481
     #8 in clone (/lib/x86_64-linux-gnu/libc.so.6+0xfcbde)

 0x604000000318 is located 8 bytes inside of 48-byte region [0x604000000310,0x604000000340)
 freed by thread T7 here:
     #0 in __interceptor_free
     #1 in metadata_bucket_destroy
     #2 in consumer_stream_free
     #3 in consumer_stream_destroy
     #4 in clean_channel_stream_list
     #5 in consumer_del_channel
     #6 in consumer_stream_destroy
     #7 in setup_metadata
     #8 in lttng_ustconsumer_recv_cmd
     #9 in lttng_consumer_recv_cmd
     #10 in consumer_thread_sessiond_poll
     #11 in start_thread nptl/pthread_create.c:481

 previously allocated by thread T7 here:
     #0 in __interceptor_calloc
     #1 in zmalloc
     #2 in metadata_bucket_create
     #3 in consumer_stream_enable_metadata_bucketization
     #4 in lttng_ustconsumer_set_stream_ops
     #5 in lttng_ustconsumer_on_recv_stream
     #6 in lttng_consumer_on_recv_stream
     #7 in create_ust_streams
     #8 in ask_channel
     #9 in lttng_ustconsumer_recv_cmd
     #10 in lttng_consumer_recv_cmd
     #11 in consumer_thread_sessiond_poll
     #12 in start_thread nptl/pthread_create.c:481

 Thread T7 created by T0 here:
     #0 in __interceptor_pthread_create
     #1 in main
     #2 in __libc_start_main ../csu/libc-start.c:332

 SUMMARY: AddressSanitizer: heap-use-after-free in metadata_bucket_destroy

This can be easily reproduced by forcing a failure during the setup
of the metadata reproducible using the following change:

  diff --git a/src/common/ust-consumer/ust-consumer.c b/src/common/ust-consumer/ust-consumer.c
  index fa1c71299..97ed59632 100644

  --- a/src/common/ust-consumer/ust-consumer.c
  +++ b/src/common/ust-consumer/ust-consumer.c
  @@ -908,8 +908,7 @@ static int setup_metadata(struct lttng_consumer_local_data *ctx, uint64_t key)

           /* Send metadata stream to relayd if needed. */
           if (metadata->metadata_stream->net_seq_idx != (uint64_t) -1ULL) {
  -                ret = consumer_send_relayd_stream(metadata->metadata_stream,
  -                                metadata->pathname);
  +                ret = -1;
                   if (ret < 0) {
                           ret = LTTCOMM_CONSUMERD_ERROR_METADATA;
                           goto error;

Cause
=====

Channels have a list of streams that are being "setup" and are not
yet monitored for consumption. During this setup phase, the streams are
owned by the channel. On destruction of the channel, any stream in that
list will thus be cleaned-up.

When destroying a consumer stream, a reference to its channel is 'put'.
This can result in the destruction of the channel.

In the situation described above, the release of the channel's reference
is done before the stream is removed from the channel's stream list.
This causes the channel's clean-up to invoke (again) the current
stream's clean-up, resulting in the double-free of the metadata bucket.

This problem is present in a number of error paths.

Solution
========

Some error paths already manually removed the consumer stream from it's
channel's stream list before invoking consumer_stream_destroy(). The
various error paths that have to deal with this possible situation are
changed to simply invoke consumer_stream_destroy().

consumer_stream_destroy() is modified to always remove the stream from
its channel's list before performing the rest of the clean-up. This
ensures that those double clean-ups can't occur.

Drawbacks
=========

None.

Reported-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
Tested-by: Vincent Whitchurch <vincent.whitchurch@axis.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ibeca9b675b86fc46be3f57826f7158de4da43df8

2 years agoFix: ust-consumerd: leak of stream control structure
Jérémie Galarneau [Thu, 3 Mar 2022 22:52:33 +0000 (17:52 -0500)] 
Fix: ust-consumerd: leak of stream control structure

The following leak is reported by LeakSanitizer when
setup_metadata() fails to send the metadata stream to the relay
daemon:

  ==3050181==ERROR: LeakSanitizer: detected memory leaks

  Direct leak of 240 byte(s) in 5 object(s) allocated from:
      #0 0x7f5fce02cfb9 in __interceptor_calloc /usr/src/debug/gcc/libsanitizer/asan/asan_malloc_linux.cpp:154
      #1 0x7f5fcdd95a7a in zmalloc ../../../src/common/macros.h:23
      #2 0x7f5fcdd95a7a in lttng_ust_ctl_create_stream /home/jgalar/EfficiOS/src/lttng-ust/src/lib/lttng-ust-ctl/ustctl.c:1649

A consumer stream can have an allocated
`struct lttng_ust_ctl_consumer_stream *` (ustream) even if it is
not globally visible at the time of its teardown.

In the case of the user space consumer, the only site that creates
consumer stream instances ensures that the allocation of the
lttng_ust_ctl_consumer_stream succeeded, ensuring that the
consumer stream's 'ustream' is always set.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ia4be7969e85bd8812ae13b042e1e100812a63c1d

2 years agoFix: liblttng-ctl: erroneous flat size computation
Jérémie Galarneau [Fri, 4 Mar 2022 20:29:12 +0000 (15:29 -0500)] 
Fix: liblttng-ctl: erroneous flat size computation

compute_flattened_size() erroneously computes (over-estimates) the size
of the allocation required to hold the flat array of struct lttng_event
returned to the user by lttng_list_{events, syscalls, tracepoints}.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I0a80ef0fa66428b7df34303804a024e80b635c69

2 years agoFix: test: babeltrace1 python bindings exposes `op_enum` as a string
Jonathan Rajotte [Thu, 3 Mar 2022 23:26:35 +0000 (18:26 -0500)] 
Fix: test: babeltrace1 python bindings exposes `op_enum` as a string

Note that `babeltrace2` is the "default" reader listed in the dependency
section of the readme but `babeltrace` is the actual reader used by the
test suite.

Change-Id: I5b47ba1e37a2671560f51ac866a7a35095be2338
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoBuild fix: relayd: mismatching function signatures
Jérémie Galarneau [Mon, 7 Mar 2022 20:17:53 +0000 (15:17 -0500)] 
Build fix: relayd: mismatching function signatures

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I4ba2e7cacbe4357ad0cdbe1dc2c85894f8bedc27

2 years agoBuild fix: use of mutable keyword in C file
Jérémie Galarneau [Mon, 7 Mar 2022 20:12:35 +0000 (15:12 -0500)] 
Build fix: use of mutable keyword in C file

4045de280 is a backport of a fix against a C++ file in which `mutable`
is used to allow an ASSERT_LOCKED check. Remove the use of mutable and
make session_has_ongoing_rotation() non-const.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Id6317ad5c271f08701c9545827f75010f5e2e55d

2 years agoFix: relayd: connection abruptly closed on viewer stream creation failure
Jérémie Galarneau [Wed, 2 Mar 2022 17:59:17 +0000 (12:59 -0500)] 
Fix: relayd: connection abruptly closed on viewer stream creation failure

Commit fe88e5175 explains (and fixes) an issue that could cause the
creation of viewer streams to fail. Currently, the error path causes the
relay daemon to abruptly close the connection to its live viewer peer.
This behaviour makes it impossible for the viewer to determine if an
error occurred or if the network connection simply failed.

Returning an `LTTNG_VIEWER_NEW_STREAMS_ERR` status code allows the
viewer to report a precise error. The viewer connection is closed since
the internal error is unlikely to be recoverable.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I557a8b66c1bd1c0bf361cfbabe962d8a6808f4f4

2 years agoFix: relayd: live client fails on clear of multi-domain session
Jérémie Galarneau [Wed, 2 Mar 2022 17:37:39 +0000 (12:37 -0500)] 
Fix: relayd: live client fails on clear of multi-domain session

Observed issue
==============

Two test cases of the clear/test_ust test suite occasionally fail in the
integration jobs testing cross-bitness (32/64) LTTng deployments.

Babeltrace fails with the following error when a clear occurs while a
live client consumes a trace:

  02-28 16:55:03.262 32362 32362 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_recv@viewer-connection.c:198 [lttng-live] Remote side has closed connection
  02-28 16:55:03.262 32362 32362 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_session_get_new_streams@viewer-connection.c:1706 [lttng-live] Error receiving get new streams reply
  02-28 16:55:03.262 32362 32362 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1665 [lttng-live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
  02-28 16:55:03.262 32362 32362 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:864 Component input port message iterator's "next" method failed: iter-addr=0x55eab7eb1170, iter-upstream-comp-name="lttng-live", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
  02-28 16:55:03.262 32362 32362 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:454 [muxer] Upstream iterator's next method returned an error: status=ERROR
  02-28 16:55:03.262 32362 32362 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:991 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x55eab7eb1120, muxer-upstream-msg-iter-wrap-addr=0x55eab7eb3a70
  02-28 16:55:03.262 32362 32362 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1415 [muxer] Cannot get next message: comp-addr=0x55eab7eb0470, muxer-comp-addr=0x55eab7eb0510, muxer-msg-iter-addr=0x55eab7eb1120, msg-iter-addr=0x55eab7eb0fb0, status=ERROR
  02-28 16:55:03.262 32362 32362 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:864 Component input port message iterator's "next" method failed: iter-addr=0x55eab7eb0fb0, iter-upstream-comp-name="muxer", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
  02-28 16:55:03.262 32362 32362 W LIB/GRAPH consume_graph_sink@graph.c:473 Component's "consume" method failed: status=ERROR, comp-addr=0x55eab7eb0760, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=1, comp-class-so-handle-addr=0x55eab7ebd910, comp-class-so-handle-path="/root/workspace/joraj_integration_base_job/deps-64/build/lib/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
  02-28 16:55:03.262 32362 32362 E CLI cmd_run@babeltrace2.c:2548 Graph failed to complete successfully

  ERROR:    [Babeltrace CLI] (babeltrace2.c:2548)
    Graph failed to complete successfully
  CAUSED BY [libbabeltrace2] (graph.c:473)
    Component's "consume" method failed: status=ERROR, comp-addr=0x55eab7eb0760,
    comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK,
    comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages
    (`text` fo", comp-class-is-frozen=1, comp-class-so-handle-addr=0x55eab7ebd910,
    comp-class-so-handle-path="/root/workspace/joraj_integration_base_job/deps-64/build/lib/babeltrace2/plugins/babeltrace-plugin-text.so",
    comp-input-port-count=1, comp-output-port-count=0
  CAUSED BY [libbabeltrace2] (iterator.c:864)
    Component input port message iterator's "next" method failed:
    iter-addr=0x55eab7eb0fb0, iter-upstream-comp-name="muxer",
    iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER,
    iter-upstream-comp-class-name="muxer",
    iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu",
    iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
  CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:991)
    Cannot validate muxer's upstream message iterator wrapper:
    muxer-msg-iter-addr=0x55eab7eb1120,
    muxer-upstream-msg-iter-wrap-addr=0x55eab7eb3a70
  CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:454)
    Upstream iterator's next method returned an error: status=ERROR
  CAUSED BY [libbabeltrace2] (iterator.c:864)
    Component input port message iterator's "next" method failed:
    iter-addr=0x55eab7eb1170, iter-upstream-comp-name="lttng-live",
    iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE,
    iter-upstream-comp-class-name="lttng-live",
    iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon",
    iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
  CAUSED BY [lttng-live: 'source.ctf.lttng-live'] (lttng-live.c:1665)
    Error preparing the next batch of messages:
    live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
  CAUSED BY [lttng-live: 'source.ctf.lttng-live'] (viewer-connection.c:1706)
    Error receiving get new streams reply
  CAUSED BY [lttng-live: 'source.ctf.lttng-live'] (viewer-connection.c:198)
    Remote side has closed connection

Looking at the relay daemon logs, we see the following error:
  DBG1 - 16:55:03.262106718 [32139/32146]: Adding new file "ust/pid/gen-ust-events-32373-20220228-165503/chan_0" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1310)
  PERROR - 16:55:03.262133333 [32139/32146]: Failed to open fs handle to ust/pid/gen-ust-events-32373-20220228-165503/chan_0, open() returned: No such file or directory (in fd_tracker_open_fs_handle() at fd-tracker/fd-tracker.cpp:548)

Cause
=====

Adding more debugging logging allows us to see the following situation
takes place:

- relay thread: Create trace chunk on session 1.
- live thread: get new streams against session 1, returns NO_NEW_STREAMS
  since the session has an 'ongoing_rotation'.
- live thread: get new streams against session 2, sees no rotation
  ongoing and attempts to open `chan_0` when creating a viewer stream

The "ongoing rotation" check was introduced in a7ceb342d and, in a
nutshell, prevents live viewers from creating new viewer streams during
a rotation.

The "ongoing rotation" state is entered when a CREATE_NEW_TRACE_CHUNK
command is issued against a session.

However, this presumes that a relay_session maps 1:1 to a session on the
session daemon's end. This isn't the case as, in multi-domain
scenarios (tracing 32-bit, 64-bit, and kernel events), a single session
daemon session can map to multiple relay_session objects. This is
because the consumer daemons maintain independant connections to the
relay daemon.

To synchronize rotations accross related relay_session instances, the
relay daemon uses the same trace chunk instances accross relay_session
instances. This means that while a trace chunk is created against a
specific relay session, it can be used by other relay_session instances.

To manage shared trace chunks between relay_sessions, the relay daemon
makes use of the trace_chunk_registry. This registry allows
relay_sessions to share trace chunk instances using a unique key tuple:
  - session daemon instance uuid,
  - session daemon session id,
  - trace chunk id.

There is no equivalent mechanism to track the "ongoing_rotation" state
accross relay_sessions originating from the same sessiond session.

In the current scenario, this causes the live client to correctly see
that no new streams are available for session 1 (say, the 32-bit user
space session). Unfortunately, this state is not entered for other
sessions (64-bit and kernel relay sessions). Hence, the viewer succeds
in acquiring new streams from session 2, exposing the race the 'ongoing
rotation' state aims to protect against.

Solution
========

Like the trace chunk instances, the "ongoing rotation" state must be
shared accross relay sessions that originate from the same session
daemon session.

To "emulate" this shared state, session_has_ongoing_rotation() checks
if any relay session originating from the same sessiond session
have an ongoing rotation. If it is the case, we temporarily prevent
live viewers from acquiring new streams.

Known drawbacks
===============

session_has_ongoing_rotation() iterates over all sessions, acquiring
their lock in the process, which is certainly undesirable from a
performance standpoint.

Optimizing this is not a great challenge, but is beyond the scope
of this immediate fix.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I457a32fa497d151ca933c25433c80665268a7c1c

2 years agofix: msgpack requires limits.h for UINT_MAX
Michael Jeanson [Thu, 5 Aug 2021 20:49:26 +0000 (16:49 -0400)] 
fix: msgpack requires limits.h for UINT_MAX

Building with '-Wundef' reveals this issue :

  unpack.c: In function ‘template_callback_array’:
  unpack.c:197:17: warning: "UINT_MAX" is not defined, evaluates to 0 [-Wundef]
    197 | #if SIZE_MAX == UINT_MAX
        |                 ^~~~~~~~
  unpack.c: In function ‘template_callback_map’:
  unpack.c:241:17: warning: "UINT_MAX" is not defined, evaluates to 0 [-Wundef]
    241 | #if SIZE_MAX == UINT_MAX
        |                 ^~~~~~~~

Change-Id: I7dadd9f7013d613509f66e67ff1beb8ae593d2bf
Signed-off-by: Michael Jeanson <mjeanson@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: liblttng-ctl: hide symbols introduced by packing fixes
Jérémie Galarneau [Thu, 3 Mar 2022 21:43:08 +0000 (16:43 -0500)] 
Fix: liblttng-ctl: hide symbols introduced by packing fixes

abidiff reports the following when comparing the ABIs of
liblttng-ctl of v2.13.0 to the stable-2.13 branch.

  12 Added functions:

    [A] 'function ssize_t lttng_event_context_create_from_payload(lttng_payload_view*, lttng_event_context**)'    {lttng_event_context_create_from_payload}
    [A] 'function void lttng_event_context_destroy(lttng_event_context*)'    {lttng_event_context_destroy}
    [A] 'function int lttng_event_context_serialize(lttng_event_context*, lttng_payload*)'    {lttng_event_context_serialize}
    [A] 'function ssize_t lttng_event_create_from_payload(lttng_payload_view*, lttng_event**, lttng_event_exclusion**, char**, lttng_bytecode**)'    {lttng_event_create_from_payload}
    [A] 'function ssize_t lttng_event_field_create_from_payload(lttng_payload_view*, lttng_event_field**)'    {lttng_event_field_create_from_payload}
    [A] 'function int lttng_event_field_serialize(const lttng_event_field*, lttng_payload*)'    {lttng_event_field_serialize}
    [A] 'function lttng_error_code lttng_event_fields_create_and_flatten_from_payload(lttng_payload_view*, unsigned int, lttng_event_field**)'    {lttng_event_fields_create_and_flatten_from_payload}
    [A] 'function int lttng_event_serialize(const lttng_event*, unsigned int, char**, char*, size_t, lttng_bytecode*, lttng_payload*)'    {lttng_event_serialize}
    [A] 'function lttng_error_code lttng_events_create_and_flatten_from_payload(lttng_payload_view*, unsigned int, lttng_event**)'    {lttng_events_create_and_flatten_from_payload}
    [A] 'function lttng_rate_policy_status lttng_rate_policy_every_n_get_interval(const lttng_rate_policy*, uint64_t*)'    {lttng_rate_policy_every_n_get_interval}
    [A] 'function lttng_rate_policy_status lttng_rate_policy_once_after_n_get_threshold(const lttng_rate_policy*, uint64_t*)'    {lttng_rate_policy_once_after_n_get_threshold}
    [A] 'function lttng_session_descriptor_status lttng_session_descriptor_get_session_name(const lttng_session_descriptor*, const char**)'    {lttng_session_descriptor_get_session_name}

The packing fix patch series exposes a number of internal symbols
through liblttng-ctl. Mark those functions as hidden.

Note that the three last functions of this report were correctly
exposed by fixes following the 2.13.0 release.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Idf98f9d22388f945913c801a3da966167e7c3f3f

2 years agoFix: rotation: hang on destroy when using scheduled rotation based on timer
Jonathan Rajotte [Mon, 14 Feb 2022 16:23:28 +0000 (11:23 -0500)] 
Fix: rotation: hang on destroy when using scheduled rotation based on timer

Observed issue
==============

The following scenario results in a hang for `lttng destroy`:

lttng create test
lttng enable-event -u -a
lttng enable-rotation --timer 100000
lttng start
lttng stop
lttng start
lttng destroy

Cause
=====

There is an imbalance in how many times we start the rotation timer.

The rotation timer is only removed on `lttng destroy` or when disabling
a time-based-rotation. On the other hand, the timer is "started"
on `lttng start` and when enabling a time based rotation.

The imbalance emerging from a start/stop/start sequence would prevent the
teardown of the session object since each time the timer is started a
reference to the session is held.

Solution
========

Do not start the rotation schedule timer if it was already launched.

Known drawbacks
=========

None.

Change-Id: Ic5b8938166358fe7629187bebdf02a09e90846c0
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: consumerd: fd still open after `lttng snapshot record` returns
Jonathan Rajotte [Wed, 9 Feb 2022 19:23:18 +0000 (14:23 -0500)] 
Fix: consumerd: fd still open after `lttng snapshot record` returns

Observed issue
=====

Using a snapshot output located on a pramfs mount:

  lttng snapshot record
  rm -rf /my_mount/my_trace_output

`rm` fails with ENOTEMPTY on rmdir for /my_mount/my_trace_output.

At that point, the lttng-consumerd daemon have an open fd on:
  /my_mount/my_trace_output/ust

Note that a sleep between both command "fixes" the issue.

Cause
=====

The reclaim for the in-registry trace chunks can happen after the LTTng
CLI returns since we use `call_rcu`.

```
static
void lttng_trace_chunk_release(struct urcu_ref *ref)

....

  if (chunk->in_registry_element) {
    struct lttng_trace_chunk_registry_element *element;

    element = container_of(chunk, typeof(*element), chunk);
    if (element->registry) {
      rcu_read_lock();
      cds_lfht_del(element->registry->ht, &element->trace_chunk_registry_ht_node);
      rcu_read_unlock();
->    call_rcu(&element->rcu_node, free_lttng_trace_chunk_registry_element);
   } else {

```

The delayed reclaim of the `lttng_trace_chunk_registry_element` can
result in lttng-consumerd holding an open fd for the "chunk directory"
of the chunk since the close() is only done during the "*fini" phase of
the chunk (`lttng_trace_chunk_fini`).

Solution
========

Considering that the rcu lookup+refcount access scheme is used for the
trace chunk object and that at that point the refcount for the trace
chunk object is effectively zero, we can move the
`lttng_trace_chunk_fini` safely outside of the
`free_lttng_trace_chunk_registry_element` call_rcu call.

Known drawbacks
=========

Even if this solves the current situation, it is important to note that
the actual object holding the reference is itself refcounted and only
close the fd on release. This means that we are still exposed to this
problem if at some point the directory handle is shared and outlives the
trace chunk for some reason in the future.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I6da3948824bf8b092fc8248b1bb0263fdd5887be

2 years agoFix: event: unchecked return value for lttng_strncpy
Jonathan Rajotte [Wed, 2 Mar 2022 15:50:16 +0000 (10:50 -0500)] 
Fix: event: unchecked return value for lttng_strncpy

Reported by Coverity:

  CID 1475806: Unchecked return value (CHECKED_RETURN)
  Calling lttng_strncpy without checking return value.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ib2b16bef61bcc24fea381c18fd8f914e9a84a6e7

2 years agoFix: event: format specifier for ssize_t
Jonathan Rajotte [Wed, 2 Mar 2022 15:36:11 +0000 (10:36 -0500)] 
Fix: event: format specifier for ssize_t

Observed issue
==============

  In file included from event.cpp:15:
  event.cpp: In function ‘ssize_t lttng_event_create_from_payload(lttng_payload_view*, lttng_event**, lttng_event_exclusion**, char**, lttng_bytecode**)’:
  ../../src/common/error.h:191:28: warning: format ‘%lu’ expects argument of type ‘long unsigned int’, but argument 4 has type ‘ssize_t’ {aka ‘int’} [-Wformat=]
    191 |  __lttng_print(PRINT_WARN, "Warning: " fmt "\n", ## args)
        |                            ^~~~~~~~~~~~~~~~~~~~
  ../../src/common/error.h:139:51: note: in definition of macro ‘__lttng_print’
    139 |    fprintf((type) == PRINT_MSG ? stdout : stderr, fmt, ## args); \
        |                                                   ^~~
  event.cpp:624:4: note: in expansion of macro ‘WARN’
    624 |    WARN("Userspace probe location from the received buffer is not the advertised length: header length = %" PRIu32 ", payload length = %lu", event_comm->userspace_probe_location_len, ret);
        |    ^~~~

Solution
========

Albeit there is no "canonical" way of printing ssize_t, use '%zd' since
we already make use of it elsewhere.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Id41e6ccf07bd580813f169b65d281a4fa305fb48

2 years agoFix: sessiond: use after free
Jonathan Rajotte [Wed, 2 Mar 2022 15:24:29 +0000 (10:24 -0500)] 
Fix: sessiond: use after free

Introduced by 88b02a8e7cbdbc728cc681cd07bbe0c738964717

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I9b1c3eeed7e51976af1a4982fc522066b3b29461

2 years agoFix: sessiond: `break` used instead of `goto`
Jonathan Rajotte [Tue, 1 Mar 2022 15:35:44 +0000 (10:35 -0500)] 
Fix: sessiond: `break` used instead of `goto`

On error path, use `goto`.

Reported by Coverity:

    CID 1475805: Unused value (UNUSED_VALUE)
    Assigning value LTTNG_ERR_UNK to ret_code here, but that stored value is overwritten before it can be used.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ife3b5486b8463242dfecb61a3a9718e8eb7149b4

2 years agoFix: sessiond: lttng_channel object is not reclaimed
Jonathan Rajotte [Tue, 1 Mar 2022 15:31:33 +0000 (10:31 -0500)] 
Fix: sessiond: lttng_channel object is not reclaimed

The reclaim is also missing on the error path.

Reported by Coverity:

    CID 1475807: Resource leak (RESOURCE_LEAK)
    Variable channel going out of scope leaks the storage it points to.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I9ae59900f6bc33282b8b8a65b834a718428a7f50

2 years agoFix: common: local_attr might leak
Jonathan Rajotte [Tue, 1 Mar 2022 15:27:37 +0000 (10:27 -0500)] 
Fix: common: local_attr might leak

Reported by Coverity:

    CID 1475808: Resource leak (RESOURCE_LEAK)
    Variable local_attr going out of scope leaks the storage it points to.

    CID 1475810: Resource leak (RESOURCE_LEAK)
    Variable local_attr going out of scope leaks the storage it points to.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ibe2ee6516618827b6f52676d9a9f7d510cadf1bc

2 years agoFix: session: end goto label used for error path
Jonathan Rajotte [Tue, 1 Mar 2022 15:23:24 +0000 (10:23 -0500)] 
Fix: session: end goto label used for error path

Reported by Coverity:

    CID 1475801: Unused value (UNUSED_VALUE)
    Assigning value LTTNG_ERR_FATAL to ret_code here, but that stored value is overwritten before it can be used

    CID 1475802: Unused value (UNUSED_VALUE)
    Assigning value LTTNG_ERR_NOMEM to ret_code here, but that stored value is overwritten before it can be used.

    CID 1475814: Unused value (UNUSED_VALUE)
    Assigning value LTTNG_ERR_UST_CHAN_NOT_FOUND to ret_code here, but that stored value is overwritten before it can be used.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I79fb5d65ea0f4f3dfbbef2a42ec3dcf0542043c5

2 years agoFix: sessiond: event, filter expression, bytecode, exclusions might leak
Jonathan Rajotte [Tue, 1 Mar 2022 15:18:46 +0000 (10:18 -0500)] 
Fix: sessiond: event, filter expression, bytecode, exclusions might leak

Reported by Coverity:

    CID 1475803: Resource leak (RESOURCE_LEAK)
    Variable filter_expression going out of scope leaks the storage it points to.

    CID 1475816: Resource leak (RESOURCE_LEAK)
    Variable exclusions going out of scope leaks the storage it points to.

    CID 1475817: Resource leak (RESOURCE_LEAK)
    Variable bytecode going out of scope leaks the storage it points to.

    CID 1475820: Resource leak (RESOURCE_LEAK)
    Variable event going out of scope leaks the storage it points to.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I705e3cc1a1894af52d6ddeee94798a887dc82bba

2 years agoFix: lttng-sessiond: event_context might leak
Jonathan Rajotte [Tue, 1 Mar 2022 14:52:21 +0000 (09:52 -0500)] 
Fix: lttng-sessiond: event_context might leak

If the parsing completed but is not the expected size, the
*out_event_context object leaks.

Reported by Coverity:

    CID 1475821 (#1 of 1): Resource leak (RESOURCE_LEAK)
    Variable event_context going out of scope leaks the storage it points to.

Change-Id: I8198f7f3f1e1af3dcb377d89674402ec49cb788b
Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: lttng-ctl: uninitialized pointer read
Jonathan Rajotte [Tue, 1 Mar 2022 14:09:04 +0000 (09:09 -0500)] 
Fix: lttng-ctl: uninitialized pointer read

Reported by Coverity:

    CID 1475822: Uninitialized pointer read (UNINIT)
    Using uninitialized value reply._fd_handles.array.size when calling lttng_payload_reset.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ied7f5de61d736e8d8f9c869a36322262a4d79cd5

2 years agoFix: ser/des: missing null terminator on payload append
Jonathan Rajotte [Tue, 1 Mar 2022 14:50:06 +0000 (09:50 -0500)] 
Fix: ser/des: missing null terminator on payload append

Reported by the lttng-ust-java-tests_master_build CI job.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I47b048c65a9855347c9b02fe44d9fdbae7e06dbf

2 years agoFix: test: test plan/skip must come after TAP initialization
Jonathan Rajotte [Tue, 1 Mar 2022 17:33:53 +0000 (12:33 -0500)] 
Fix: test: test plan/skip must come after TAP initialization

TAP is initialized during the sourcing of `utils.sh`. Calling it before
yield nothing.

Move the platform validation after the `PLAN_TEST` call.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ib7b4434440ed7590b39b0580ea294045ace40495

2 years agoFix: test: missing test plan for non-x86/arm platforms (i.e powerpc)
Jonathan Rajotte [Tue, 1 Mar 2022 02:30:44 +0000 (21:30 -0500)] 
Fix: test: missing test plan for non-x86/arm platforms (i.e powerpc)

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I9a34a0b45fd011943436ce6e45c8f0d1666df26f

2 years agoFix: remove debugging output
Jonathan Rajotte [Tue, 1 Mar 2022 02:23:53 +0000 (21:23 -0500)] 
Fix: remove debugging output

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I7bcdb7c47f811cf99dee1e4e483cc22847f481c5

2 years agoFix: tests: test_kernel: break should only be used in loops
Jérémie Galarneau [Thu, 24 Feb 2022 19:06:28 +0000 (14:06 -0500)] 
Fix: tests: test_kernel: break should only be used in loops

Using `break` in a function's scope makes no sense in bash. I am
guessing the original author meant to exit early from the various tests.

Regardless, the rest of the test can be ran without issues. I am not
sure traces of failed tests should be kept, but that's a separate issue.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I286ccb796afbbca4e3866e6fd0b35a3746045346

2 years agoFix: tools/snapshots/test_kernel flaky test
Mathieu Desnoyers [Thu, 24 Feb 2022 17:24:45 +0000 (12:24 -0500)] 
Fix: tools/snapshots/test_kernel flaky test

When tracing all system calls, nothing guarantees that the first system
call won't come from some _other_ program on the system, on a CPU != 0,
and stay invariant between the two snapshots (when it should not be).

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Iba45664f10eea0a757f8ac4eb9a7c7c75c305eef

2 years agoTests: Fix: test_list_triggers_cli: support in-kernel builtin lttng-modules
Francis Deslauriers [Thu, 25 Mar 2021 17:13:45 +0000 (13:13 -0400)] 
Tests: Fix: test_list_triggers_cli: support in-kernel builtin lttng-modules

This commit changes the grep call to remove the [lttng_tracer] string
from the pattern. When building the lttng modules directly in the kernel
there is not mention of [lttng_tracer].

Furthermore, the symbol type "t" is "T" in my test VM. The difference
may be due to the builtin nature of lttng on this VM.

Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I046905dc51524c23ad3671b66614b86a084ef8e2
Depends-on: lttng-ust: If1f29dd64538bc5979d3e89aa5cca3be4e41046f

2 years agoFix: lttng: truncated addresses and offsets on 32-bit builds
Jérémie Galarneau [Wed, 23 Feb 2022 22:40:06 +0000 (17:40 -0500)] 
Fix: lttng: truncated addresses and offsets on 32-bit builds

The lttng client parses hexadecimal addresses using, at some point,
strtoul(). Using this function effectively caps addresses and
offsets to MAX_UINT32 resulting in failures to enable kprobes
against a 64-bit kernel using a 32-bit client.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: If619e9e84413de5cd32d8c06f363152caaf5ac46

2 years agoFix: liblttng-ctl comm: lttng_event_field is not packed
Jonathan Rajotte [Wed, 12 Jan 2022 23:18:08 +0000 (18:18 -0500)] 
Fix: liblttng-ctl comm: lttng_event_field is not packed

Observed issue
==============

For MI testing where the lttng-sessiond is 64 bit and the lttng CLI is
32 bit, the tracepoint field listing fails with partial garbage output.

The size of the struct differs between bitness for x86-64 and x86
leading to serialization/deserialization problem across client
(liblttng-ctl) and lttng-sessiond.

sizeof(struct lttng_event_field):

  x86: 1136
  x86-64: 1144

The struct cannot be marked as LTTNG_PACKED since it is part of the API.

Solution
========

Adopt a similar pattern to the new APIs with a "serialize" &
"create_from_buffer" approach. The only particularity is that we need to
flatten the event_field on listing.

Most of the complexity is moved to `src/common/event.c`

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: I280d9809d110237574e2606ee93a7aeba41e704e

2 years agoFix: liblttng-ctl comm: lttng_event_context is not packed
Jonathan Rajotte [Wed, 12 Jan 2022 23:18:08 +0000 (18:18 -0500)] 
Fix: liblttng-ctl comm: lttng_event_context is not packed

Observed issue
==============

The size of the struct differs between bitness for x86-64 and x86
leading to serialization/deserialization problem across client
(liblttng-ctl) and lttng-sessiond.

sizeof(struct lttng_event_context):

  x86: 308
  x86-64: 312

The struct cannot be marked as LTTNG_PACKED since it is part of the API.

Solution
========

Adopt a similar pattern to the new API with a "serialize" &
"create_from_buffer" approach.

Most of the complexity is moved to `src/common/event.c`

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: Ieb400eab2a2df4070ff51cb2b44929d3ea945ce4

2 years agoFix: liblttng-ctl comm: lttng_event is not packed
Jonathan Rajotte [Wed, 12 Jan 2022 23:18:08 +0000 (18:18 -0500)] 
Fix: liblttng-ctl comm: lttng_event is not packed

Observed issue
==============

In `lttcomm_session_msg` the lttng_event struct is marked as
LTTNG_PACKED. This statement have no effect as explained in commit [2].

Solution
========

Adopt a similar pattern to the new API with a "serialize" &
"create_from_buffer" approach.

Most of the complexity is moved to `src/common/event.c`

Known drawbacks
=========

None.

Note
====

Jérémie Galarneau: This patch was extensively modified from the original
patch applying against stable-2.12 to accomodate for the use of the
lttng_payload utils throughout the liblttng-ctl <-> lttng-sessiond
communication code.

Some changes were also made to build as C++.

Reference
========
[1] https://review.lttng.org/gitweb?p=lttng-tools.git;a=commit;h=7bd95aee4660c6419a4a65429fc27754481e7e90

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I35d848519dacb2b119324e88f262aa95951e4ac6

2 years agolibcommon: move event.c to libcommon-lgpl
Jonathan Rajotte [Sat, 29 Jan 2022 00:29:58 +0000 (19:29 -0500)] 
libcommon: move event.c to libcommon-lgpl

The `event.c` license is already LGPL. There is no technical reason why
it was not part of the lgpl side of libcommon, simply that nothing that
is LGPL needed it. This will change in upcoming commits with the
addition of ser/des functions of `struct lttng_event` and other structs
related to `lttng_event` for liblttng-ctl.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I1e15a547e526198f971a287a726d0e6229a733b0

2 years agoFix: liblttng-ctl comm: lttng_channel is not packed
Jonathan Rajotte [Wed, 12 Jan 2022 23:18:08 +0000 (18:18 -0500)] 
Fix: liblttng-ctl comm: lttng_channel is not packed

Observed issue
==============

The size of the struct differs between bitness for x86-64 and x86
leading to serialization/deserialization problem across client
(liblttng-ctl) and lttng-sessiond.

sizeof(struct lttng_channel):

  x86: 608
  x86-64: 624

The struct cannot be marked as LTTNG_PACKED since it is part of the API.

Solution
========

Adopt a similar pattern to the new API with a "serialize" &
"create_from_buffer" approach. The only particularity is that we need to
flatten the channels on listing.

Most of the complexity is moved to `src/common/channel.c`

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: Id5c9aaf3cf8b3d739b71263c02cae8d4d2fedfe3

2 years agoFix: conversion from KB to bytes overflow on arm32
Jonathan Rajotte [Thu, 27 Jan 2022 19:22:22 +0000 (14:22 -0500)] 
Fix: conversion from KB to bytes overflow on arm32

Observed issue
==============

On enable channel the memory available check fails on arm32 when
available memory, in bytes, is larger than 2^32.

Cause
=====

`read_proc_meminfo_field` converts the read value (in KB) to bytes and
stores it into a size_t variable.

On the system running the reproducer the value of the `value_kb` variable
is 4839692, yielding an overflow when multiplied with 1024 since
`size_t` is 32 bit long. `size_t` can be larger in certain situation
(i.e LARGEFILE) but this is irrelevant to the problem at hand.

Solution
========

Convert all the checks to use uint64_t.

Known drawbacks
=========

None.

References
==========

The multiplication overflow check scheme is borrowed from
`src/common/time.c`

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I067da25659ab4115e5494e48aab45a1c35f56652

2 years agoFix: Unexpected payload size in cmd_recv_stream_2_11
Jonathan Rajotte [Tue, 11 Jan 2022 17:28:15 +0000 (12:28 -0500)] 
Fix: Unexpected payload size in cmd_recv_stream_2_11

Observed issue
==============

For the following scenario:

 lttng-relayd: 64 bit
 lttng-sessiond: 64 bit
 lttng-consumerd: 32 bit
 application: 32 bit

 Commands
   lttng create --set-url=net://127.0.0.1
   lttng enable-event -u -a
   lttng start
   ./application

On application start the lttng-relayd reports this error:

  DEBUG1 - 14:16:38.216442600 [2004731/2004735]: Done receiving control command payload: fd = 19, payload size = 4376 bytes (in relay_process_control_receive_payload() at main.c:3456)
  DEBUG3 - 14:16:38.216469462 [2004731/2004735]: Processing "RELAYD_ADD_STREAM" command for socket 19 (in relay_process_control_command() at main.c:3327)
  Error: Unexpected payload size in "cmd_recv_stream_2_11": expected >= 3519925694 bytes, got 4376 bytes

Cause
=====

In `relayd_add_stream`, instead of taking the > 2.11 protocol path, the
`relayd_add_stream_2_2` function is called.

The value of the rsock version number are:

  major: 21845
  minor: 2

Which is simply invalid since we know that the version should be 2.12.

The relayd sock version numbers are set during the
LTTNG_CONSUMER_ADD_RELAYD_SOCKET command between the lttng-sessiond and
the lttng-consumerd process. It is important to note here that both
processes do NOT have the same bitness.

The serialization and deserialization of `struct lttcomm_relayd_sock` is
the culprit.

`struct lttcomm_relayd_sock` contains a `struct lttcomm_sock`:

struct lttcomm_sock {
    int32_t fd;
    enum lttcomm_sock_proto proto;
    struct lttcomm_sockaddr sockaddr;
    const struct lttcomm_proto_ops *ops;
} LTTNG_PACKED;

Note that `ops` is a pointer and its size varies based on the bitness of
the application. Hence the size of the `struct lttcomm_sock` differs
across bitness. Since it is the first member of `struct
lttcomm_relayd_sock`, the memory layout is simply invalid across
bitness (amd64/x86).

This results in invalid parsing for the overall "struct
lttcomm_relayd_sock" when dealing with a lttng-consumerd with a
different bitness than the lttng-sessiond. As far as I know local
tracing scenarios are not affected since this is only relevant when
dealing with a lttng-relayd.

Solution
========

Pass the socket protocol type, relayd major, relayd minor in
`lttcomm_consumer_msg`. On the receiver side, query the network stack to
get the peer information to populate a basic `lttcomm_sock`. Leaving
this work to the OS saves us from having to serialize the `sockaddr_in*`
structs.

Known drawbacks
=========

We rely on `getpeername` for the first time. Compatibility might be a
problem.

This code path assumes a lot of thing that cannot be asserted against
such as the fact that the socket from which we fetch the info must be
`connected`. Still at this point, the socket is completely setup and the
rest of the code depends on it already.

From GETPEERNAME(2):

```
       For stream sockets, once a connect(2) has been performed, either
       socket can call getpeername() to obtain the address of the peer
       socket.  On the other hand, datagram sockets  are connectionless.
       Calling connect(2) on a datagram socket merely sets the peer
       address for outgoing datagrams sent with write(2) or recv(2).
       The caller of connect(2) can use getpeername() to obtain the
       peer address that it earlier set for the socket.  However, the
       peer socket is unaware of this information, and calling
       getpeername() on the  peer  socket will  return  no useful
       information (unless a connect(2) call was also executed on the
       peer).  Note also that the receiver of a datagram can obtain the
       address of the sender when using recvfrom(2).
```

But here we are always "the caller of connect".

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ic157c4137b2f20e394c907136687fcbd126f90a0

2 years agoFix: liblttng-ctl: missing index allocator symbols
Jérémie Galarneau [Tue, 22 Feb 2022 22:59:16 +0000 (17:59 -0500)] 
Fix: liblttng-ctl: missing index allocator symbols

abidiff reports that 5 functions were erroneously removed by the 2.13.4
release. Those functions were initially erroneously exposed, but the
symbols must be maintained to preserve the ABI of liblttng-ctl.

abidiff report:
  5 Removed functions:

    [D] 'function lttng_index_allocator_status lttng_index_allocator_alloc(lttng_index_allocator*, uint64_t*)'    {lttng_index_allocator_alloc}
    [D] 'function lttng_index_allocator* lttng_index_allocator_create(uint64_t)'    {lttng_index_allocator_create}
    [D] 'function void lttng_index_allocator_destroy(lttng_index_allocator*)'    {lttng_index_allocator_destroy}
    [D] 'function uint64_t lttng_index_allocator_get_index_count(lttng_index_allocator*)'    {lttng_index_allocator_get_index_count}
    [D] 'function lttng_index_allocator_status lttng_index_allocator_release(lttng_index_allocator*, uint64_t)'    {lttng_index_allocator_release}

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I7d69a0526ccb9ba69ddfbad6955c81146bb83698

2 years agoFix: lttng-sessiond: null pointer used to log session name
Jérémie Galarneau [Tue, 22 Feb 2022 22:46:14 +0000 (17:46 -0500)] 
Fix: lttng-sessiond: null pointer used to log session name

The rotation thread attempts to log the name of a session
when it isn't found.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I7bd3f9e82cadc9f1c8acbb847a88e0ff1ed813e3

2 years agoTests: add kernel test into the `make check` test suite.
Jonathan Rajotte [Mon, 31 Jan 2022 19:47:35 +0000 (14:47 -0500)] 
Tests: add kernel test into the `make check` test suite.

The Jenkins CI mostly run the `make check` suite. Only the Lava base CI
run the root_regression test suite. Most of those test can be run on
`make check` without incurring any major extra time.

Only `regression/tools/streaming/test_high_throughput_limits` is left in
root_regression since it is currently "unreasonable" in term of the time
it takes to run. This could be tackled another time.

Signed-off-by: Jonathan Rajotte <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I3d59705e84549c2a1840cf96a7723396e2e0c402

2 years agoBuild dist fix: some kernel tests are not distributed
Jérémie Galarneau [Wed, 9 Feb 2022 00:41:10 +0000 (19:41 -0500)] 
Build dist fix: some kernel tests are not distributed

A missing '\' causes some kernel test scripts to not be added
the EXTRA_DIST variable. This causes those tests to not be
shipped as part of the tarball.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I3c824b4c7ea913cb4cdc7ac6f98df05267ca5764

2 years agoTests: fix: test_kernel_function: erroneous test count
Jérémie Galarneau [Thu, 10 Feb 2022 22:53:56 +0000 (17:53 -0500)] 
Tests: fix: test_kernel_function: erroneous test count

The test_kernel_function test runs one extra test which causes it to be
marked as failed. Adjust the count to fit the number of tests.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ia861cf7b0123fdf19405bb84271ddda76f9fd6e7

2 years agoTests: fix: test_kernel_function: event name mismatch
Jérémie Galarneau [Wed, 9 Feb 2022 22:00:40 +0000 (17:00 -0500)] 
Tests: fix: test_kernel_function: event name mismatch

The test_kernel_function test expects the name of the function
exit event to be suffixed with "_return". This was changed to
"_exit" during the development of the 2.13 release.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I6e7f85af33699b2bf0439f74343d521f896594e1

2 years agoTests: fix: select_poll_epoll: test assumes epoll fd value
Jérémie Galarneau [Thu, 10 Feb 2022 16:59:31 +0000 (11:59 -0500)] 
Tests: fix: select_poll_epoll: test assumes epoll fd value

The test currently assumes that epoll fds are always == 3, which
is not always the case depending on the execution environment.

This change causes `select_poll_epoll` to produce a JSON file
containing the application's pid and epoll fd values that is
then used by the validation script.

Note that the test is converted to C++ to allow the use of
internal utils (common/error.h/cpp) without changing their linkage.

However, the code is still regular C to ease the backport of this
fix.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ie373c63f6e6b9267ae2d785c9f0a532a5de37905

2 years agoFix: missing RCU read side critical sections
Jérémie Galarneau [Fri, 28 Jan 2022 22:59:46 +0000 (17:59 -0500)] 
Fix: missing RCU read side critical sections

Based on the comments of the called functions.

Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ica81b648ce88290c4ca7507fb00a78480457cf01

2 years agoUpdate version to v2.13.4 v2.13.4
Jérémie Galarneau [Thu, 27 Jan 2022 01:46:17 +0000 (20:46 -0500)] 
Update version to v2.13.4

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoBuild fix: hashtable: hashtable.cpp does not exist
Jérémie Galarneau [Wed, 26 Jan 2022 22:37:32 +0000 (17:37 -0500)] 
Build fix: hashtable: hashtable.cpp does not exist

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I26df82f015c23673a56fd7a684b3bbb1f2df9b16

2 years agoUpdate version to v2.13.3 v2.13.3
Jérémie Galarneau [Wed, 26 Jan 2022 22:30:54 +0000 (17:30 -0500)] 
Update version to v2.13.3

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: _lttng_variant_statedump should expect lttng_ust_ctl_atype_variant_nestable
Mathieu Desnoyers [Wed, 26 Jan 2022 15:53:55 +0000 (10:53 -0500)] 
Fix: _lttng_variant_statedump should expect lttng_ust_ctl_atype_variant_nestable

The precondition check in _lttng_variant_statedump is too strict: it
should also expect lttng_ust_ctl_atype_variant_nestable. Remove this
check entirely, which is redundant with the switch/case in the only
caller sites in the same compile unit.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I744cc5cef69ff29f8d7ecc1cf01c9a629c6e222e

2 years agoFix context mismatch across UST version due to legacy array context field
Mathieu Desnoyers [Mon, 24 Jan 2022 22:05:39 +0000 (17:05 -0500)] 
Fix context mismatch across UST version due to legacy array context field

Observed issue
==============

Tracing applications linked against both LTTng-UST 2.12.x and 2.13.1 in
the same session fails with:

"Error: Registering application channel due to context field mismatch"

for some applications with the "procname" context enabled.

Cause
=====

The procname context uses the legacy array field type prior to LTTng-UST
2.13, and uses the array_nestable field type starting from LTTng-UST
2.13. The field comparison in lttng-sessiond is unaware of the fact that
they map to the exact same binary trace layout and are therefore
compatible.

Solution
========

Introduce a new fixup function "ust_app_fixup_legacy_context_fields" in
lttng-sessiond for channel context fields, which detects the presence of
the legacy array, struct and variant types, and rewrites them as
array_nestable, struct_nestable, and variant_nestable types.

Reject the legacy sequence type in channel context fields because it is
not used by LTTng-UST 2.12 and older.

Rewriting those legacy context types as the new "nestable" types ensures
that field comparison functions will correctly handle a mix of 2.12 and
2.13 LTTng-UST tracers using a procname context to a given session's
channel.

Known Drawbacks
===============

None.

Fixes: fb2772932 ("Validate channel context mismatch across UST applications")
Change-Id: Ic51b92130ae8e1f7b510924f78ff46459dc2f578
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoRelicence all source and header files included in LGPL code
Mathieu Desnoyers [Wed, 12 Jan 2022 21:46:21 +0000 (16:46 -0500)] 
Relicence all source and header files included in LGPL code

All code included in libcommon-lgpl.a should be LGPL. Some were licensed
as GPLv2 by mistake. We need to relicense those.

EfficiOS owns the copyright to all of the affected source files and
agrees to this relicensing from GPLv2 to LGPLv2.1.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ib4aa1a7cc8a6f8e2a9891f1bd05c7ea2f8530e9b

2 years agoMove utils_expand_path and utils_expand_path_keep_symlink to libpath.la
Mathieu Desnoyers [Wed, 19 Jan 2022 16:35:20 +0000 (11:35 -0500)] 
Move utils_expand_path and utils_expand_path_keep_symlink to libpath.la

Move the GPLv2 helper functions utils_expand_path and
utils_expand_path_keep_symlink to libpath.la. This will allow utils.cpp
to be relicensed to LGPLv2.1 by making sure EfficiOS owns the copyright
for the entire source file.

Statically include libpath.la into libcommon-gpl.la.

The "lttng" executable is GPLv2 and only depends on libcommon-lgpl.la,
so it needs to explicitly list libpath.la as its dependency.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I2108e0bd35ce75797d4a20e65891c820a1dd79f8

2 years agoLink lttng executable on libcommon-lgpl.a
Mathieu Desnoyers [Wed, 12 Jan 2022 20:23:09 +0000 (15:23 -0500)] 
Link lttng executable on libcommon-lgpl.a

Allows testing whether liblttng-ctl.so has any dependency on
libcommon-gpl.a. Will trigger a link-time failure if it is the case.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ie6f864dccdd61f896a7e238e202dc6188ec4f9c5

2 years agoIntroduce libcommon-lgpl for liblttng-ctl
Mathieu Desnoyers [Tue, 11 Jan 2022 20:57:37 +0000 (15:57 -0500)] 
Introduce libcommon-lgpl for liblttng-ctl

liblttng-ctl is a LGPLv2.1 library should should not use GPLv2 code.
Introduce libcommon-lgpl as a static archive containing only LGPLv2.1
compatible code.

This also removes the dependency from liblttng-ctl to liburcu.

Include some source files in libcommon-lgpl.a which are indirectly needed
by source files required in libcommon-lgpl.a:

- endpoint.cpp,
- lttng-elf.cpp,
- lttng-elf.h.

Include some source files in libcommon-lgpl.a which are only needed to
link the lttng executable:

- domain.cpp,
- spawn-viewer.cpp, spawn-viewer.h.

Introduce the new source file hashtable/seed.cpp to move the
lttng_ht_seed symbol in a source file which does not require
liburcu-cds, so it can be present in libcommon-lgpl. This allows
building compile units which are needed in the lgpl common library which
also contain functions which directly refer to lttng_ht_seed.

Programs and libraries which use libhashtable.la are changed to use
libcommon-gpl.la instead. libhashtable becomes internal to libcommon.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I27d2acb823a6d951692a5da88ce32bbe6bafb072

2 years agoRename libcommon.so to libcommon-gpl.so
Mathieu Desnoyers [Tue, 11 Jan 2022 19:46:37 +0000 (14:46 -0500)] 
Rename libcommon.so to libcommon-gpl.so

libcommon is a static library is currently used by both liblttng-ctl
(LGPLv2.1) and all lttng-tools executables (GPLv2).

Given that some code in libcommon depends on liburcu, this introduces an
indirect dependency from liblttng-ctl to liburcu, which is unwanted.

This first step renames libcommon.so to libcommon-gpl.so. Following
steps will introduce a more lightweight libcommon-lgpl.so which only
contains LGPLv2.1 code, and removes the dependency on liburcu.

Backport Notes
--------------

ini_config has to link against liblttng-ctl since since the internal
configuration library is not split into ini-config and libconfig
(see 3299fd310).

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ia8f37ea229f68550200cbb1528216a505bbbd45f

2 years agoCopyright ownership transfer
Mathieu Desnoyers [Thu, 20 Jan 2022 15:30:01 +0000 (10:30 -0500)] 
Copyright ownership transfer

Apply copyright ownership transfer from Jonathan Rajotte-Julien and
Olivier Cotte to EfficiOS Inc.

Link: https://lists.lttng.org/pipermail/lttng-dev/2022-January/030111.html
Link: https://lists.lttng.org/pipermail/lttng-dev/2022-January/030113.html
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Olivier Moussavou Cotte <olivier.moussavoucotte@mail.mcgill.ca>
Signed-off-by: Jonathan Rajotte-Julien <jonathan.r.julien@gmail.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I0c2800ec17f5d435c8a18f2dae096809b8037b5d

2 years agoCopyright ownership transfer
Jérémie Galarneau [Fri, 14 Jan 2022 20:42:03 +0000 (15:42 -0500)] 
Copyright ownership transfer

Apply copyright ownership transfer from David Goulet, Julien Desfossez,
and Simon Marchi to EfficiOS Inc.

Link: https://lists.lttng.org/pipermail/lttng-dev/2022-January/030087.html
Link: https://lists.lttng.org/pipermail/lttng-dev/2022-January/030092.html
Link: https://lists.lttng.org/pipermail/lttng-dev/2022-January/030091.html
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Signed-off-by: David Goulet <dgoulet@ev0ke.net>
Signed-off-by: Julien Desfossez <ju@klipix.org>
Signed-off-by: Simon Marchi <simon.marchi@efficios.com>
Change-Id: Id13575afd4a2a09bb91a8d2b7a12dc3db8dc329f

2 years agoFix: relayd: erroneous rundir permission logging message
Jérémie Galarneau [Fri, 23 Jul 2021 20:56:53 +0000 (16:56 -0400)] 
Fix: relayd: erroneous rundir permission logging message

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I2eb0901896feab684d397aa43f8c9036018d9c95

2 years agoFix: sessiond: rotation thread: fatal error when not finding a session
Jérémie Galarneau [Thu, 9 Dec 2021 21:27:29 +0000 (16:27 -0500)] 
Fix: sessiond: rotation thread: fatal error when not finding a session

The rotation thread implements scheduled rotations (by size) by
registering a trigger that monitors the session's consumed size and
notifies when the next rotation's size threshold is exceeded.

The notification is delivered asynchronously which doesn't prevent
the session from being destroyed before the rotation thread has
had the time to process the notification (and perform a rotation).

Since it is possible for a session to be destroyed by the time the
notification is processed, the rotation thread shouldn't handle
this eventuality as a fatal error (shutting down the thread).

Note that nobody reported this issue nor did I attempt to reproduce it.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I588054bad3542854851f28d34f2c758bdf420a34

2 years agoFix: relayd: rotation failure for multi-domain session
Jérémie Galarneau [Wed, 12 Jan 2022 20:48:00 +0000 (15:48 -0500)] 
Fix: relayd: rotation failure for multi-domain session

Observed issue
==============

Rotating a multi-domain streaming session results in the following
error:

  $ lttng rotate
  Waiting for rotation to complete...
  Error: Failed to retrieve rotation state.

Meanwhile, the relay daemon logs indicate the following:

  DBG1 - 14:56:04.213163667 [265774/265778]: lttng_trace_chunk_rename_path from .tmp_new_chunk to (null) (in lttng_trace_chunk_rename_path_no_lock() at trace-chunk.cpp:759)
  PERROR - 14:56:04.213242941 [265774/265778]: Failed to move trace chunk directory ".tmp_new_chunk" to "20220112T145604-0500-1": No such file or directory (in lttng_trace_chunk_rename_path_no_lock() at trace-chunk.cpp:799)
  DBG1 - 14:56:04.213396931 [265774/265778]: aborting session 2 (in session_abort() at session.cpp:588)
  DBG1 - 14:56:04.213512198 [265774/265778]: Control connection closed with 22 (in relay_thread_close_connection() at main.cpp:3874)

The 'abort' of session 2 here causes the kernel consumer to fail to
consume subbuffers:

  Error: Relayd send index failed. Cleaning up relayd 3.
  Error: Error consuming subbuffer: (0)
  [...]

Cause
=====

Following the flow of execution in the relay daemon shows that different
trace chunks are used by the two relay sessions that result from the
streaming of a single multi-domain session. Both trace chunks "own" the
same output directory.

When a rotation is performed, the first trace chunk to be closed will
move the directory. Then, the second trace chunk to be closed will
attempt to do the same, failing to do so as seen in the relay daemon
log.

Solution
========

Using different trace chunk instances for relay sessions belonging to a
single sessiond session goes against the intended use of the sessiond
trace chunk registry.

A sessiond trace chunk registry allows the relay daemon to share trace
chunks used by different "relay sessions" when they were created for the
same user-visible session daemon session. Tracing multiple domains (e.g.
ust and kernel) results in per-domain relay sessions being created.

Sharing trace chunks, and their output directory more specifically, is
essential to properly implement session rotations. The sharing of output
directory handles allows directory renames to be performed once and
without races that would stem from from multiple renames.

The reason why sessiond trace chunk registry returns different trace
chunk instances for two relay sessions is that the wrong session `id` is
used to publish trace chunks. The `id` that must be used to share trace
chunks accross the relay sessions that belong to the same sessiond
session is `id_sessiond`.

`id_sessiond` is optional as it is only provided by consumers v2.11+.
Otherwise, it is fine to use the relay session `id`: it is a unique id
for a given session daemon instance and those consumers will not issue a
session rotation (or clear) as the feature didn't exist.

A reference counting bug revealed by this change is also fixed in the
implementation of the sessiond trace chunk registry.

When the trace chunk is first published, two references to the published
chunks exist. One is taken by the registry while the other is being
returned to the caller. In the use case of the relay daemon, the
reference held by the registry itself is undesirable.

We want the trace chunk to be removed from the registry as soon as it is
not being used by the relay daemon (through a session or a stream). This
differs from the behaviour of the consumer daemon which relies on an
explicit command from the session daemon to release the registry's
reference.

In cases where the trace chunk had already been published, the reference
belonging to the sessiond trace chunk registry instance has already been
'put' by the firt publication. We must simply return the published trace
chunk with a reference taken on behalf of the caller.

Known drawbacks
===============

None.

Change-Id: Ic33443b114a87574a1b26ac5ccb022e47f886ddd
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: lttng-ctl: lttng_list_sessions: initialize out_sessions to NULL when returning 0
Mathieu Desnoyers [Tue, 11 Jan 2022 18:59:15 +0000 (13:59 -0500)] 
Fix: lttng-ctl: lttng_list_sessions: initialize out_sessions to NULL when returning 0

Observed issue
==============

Users of lttng-ctl API's lttng_list_sessions observe application crash
when freeing the *out_sessions output value when lttng_list_sessions
returns 0.

Cause
=====

The implementation does not set *out_sessions to NULL when
lttng_ctl_ask_sessiond() sets the sessions variable to NULL.
This causes the user application to attempt to free(3) an uninitialized
pointer.

Solution
========

Initialize out_sessions to NULL before invoking
lttng_ctl_ask_sessiond(), so it is initialized when lttng_list_sessions
returns 0, thus allowing *out_sessions to be subsequently freed.
A free(3) on a NULL pointer is a no-op.

Known drawbacks
===============

None.

History
=======

This was introduced by those two commits:

b178f53e90 ("Generate session name and default output on sessiond's end")
27ea4ba825 ("Fix: error when listing sessions with no session")

This is a regression present in the stable-2.11, stable-2.12,
stable-2.13, and master branches.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I34125d708a32674d79b831e5004c48321ebd711e

2 years agoFix: lttng: initialize variable in run_command_string
Simon Marchi [Tue, 30 Nov 2021 03:15:53 +0000 (22:15 -0500)] 
Fix: lttng: initialize variable in run_command_string

I got some crashes when using `lttng track` and hitting some error
paths.  The tracker_handle variable is run_command_string is passed to
lttng_process_attr_tracker_handle_destroy uninitialized if
lttng_session_get_tracker_handle fails.

    $ valgrind lttng track --kernel --pid 569878
    ==634572== Memcheck, a memory error detector
    ==634572== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
    ==634572== Using Valgrind-3.17.0 and LibVEX; rerun with -h for copyright info
    ==634572== Command: lttng track --kernel --pid 569878
    ==634572==
    Error: Unknown error
    ==634572== Conditional jump or move depends on uninitialised value(s)
    ==634572==    at 0x4875007: lttng_process_attr_tracker_handle_destroy (tracker.cpp:25)
    ==634572==    by 0x13AC55: run_command_string(cmd_type, char const*, lttng_domain_type, lttng_process_attr, char const*, mi_writer*) (track-untrack.cpp:485)
    ==634572==    by 0x13ADA5: run_command(cmd_type, char const*, process_attr_command_args const*, mi_writer*) (track-untrack.cpp:535)
    ==634572==    by 0x13B472: cmd_track_untrack(cmd_type, int, char const**, char const*) (track-untrack.cpp:740)
    ==634572==    by 0x13B5D9: cmd_track(int, char const**) (track-untrack.cpp:805)
    ==634572==    by 0x14C598: handle_command(int, char**) (lttng.cpp:237)
    ==634572==    by 0x14CCE9: parse_args(int, char**) (lttng.cpp:426)
    ==634572==    by 0x14CE65: main (lttng.cpp:475)

Fix it by initializing it to NULL.

Change-Id: Id2693e75c3c5c83cef58db3109973d7ab679b859
Signed-off-by: Simon Marchi <simon.marchi@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoFix: consumer-stream: live viewers observe timestamps going backwards
Mathieu Desnoyers [Mon, 22 Nov 2021 19:38:35 +0000 (14:38 -0500)] 
Fix: consumer-stream: live viewers observe timestamps going backwards

Observed issue
==============

When stress-testing over an entire weekend, we caught the following
occurrences of timestamps going backwards with babeltrace in live viewer
mode:

One occurrence:

  # Test ust streaming live clear with viewer with new metadata after clear
  # Parameters: tracing_active=0, clear_twice=0, buffer_type=pid

6-7 occurrences:

  # Test ust basic streaming live with viewer
  # Parameters: tracing_active=1, clear_twice=0, buffer_type=uid

Relevant log of the relayd focused on the context of the stream
triggering the issue (stream 994):

506:DBG1 - 17:26:54.966288486 [3866648/3866655]: Relay viewer stream 994 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:268)
603:DBG1 - 17:26:54.970265349 [3866648/3866655]: Sending stream 994 to viewer (in send_viewer_streams() at live.cpp:241)
843:DBG1 - 17:26:55.959835404 [3866648/3866652]: stream_add_index for stream 994 (in stream_add_index() at stream.cpp:1233)
844:DBG3 - 17:26:55.959866303 [3866648/3866652]: Finding index for stream id 994 and seq_num 0 (in relay_index_get_by_id_or_create() at index.cpp:112)
845:DBG2 - 17:26:55.959896611 [3866648/3866652]: Creating relay index for stream id 994 and seqnum 0 (in relay_index_create() at index.cpp:34)
846:DBG2 - 17:26:55.959928097 [3866648/3866652]: Adding relay index with stream id 994 and seqnum 0 (in relay_index_add_unique() at index.cpp:70)
847:DBG2 - 17:26:55.959968163 [3866648/3866652]: Index found or created in HT for stream ID 994 and seqnum 0 (in relay_index_get_by_id_or_create() at index.cpp:144)
884:DBG3 - 17:26:55.961676906 [3866648/3866652]: Receiving data for stream id 994 seqnum 0, 0 bytes received, 84 bytes left to receive (in relay_process_data_receive_payload() at main.cpp:3583)
885:DBG1 - 17:26:55.961783540 [3866648/3866652]: Wrote to stream 994: data_length = 84, padding_length = 0 (in stream_write() at stream.cpp:1113)
886:DBG1 - 17:26:55.961862441 [3866648/3866652]: Wrote to stream 994: data_length = 0, padding_length = 4012 (in stream_write() at stream.cpp:1113)
887:DBG1 - 17:26:55.961895593 [3866648/3866652]: handle_index_data: stream 994 net_seq_num 0 data offset 0 (in stream_update_index() at stream.cpp:1140)
888:DBG3 - 17:26:55.961945901 [3866648/3866652]: Finding index for stream id 994 and seq_num 0 (in relay_index_get_by_id_or_create() at index.cpp:112)
889:DBG2 - 17:26:55.961983056 [3866648/3866652]: Index found or created in HT for stream ID 994 and seqnum 0 (in relay_index_get_by_id_or_create() at index.cpp:144)
894:DBG2 - 17:26:55.962334285 [3866648/3866652]: Writing index for stream ID 994 and seq num 0 (in relay_index_try_flush() at index.cpp:275)
895:DBG2 - 17:26:55.962390756 [3866648/3866652]: index put for stream id 994 and seqnum 0 refcount 1 (in relay_index_put() at index.cpp:237)
1743:DBG1 - 17:26:56.083287172 [3866648/3866655]: Check index status: index_received_seqcount 1 index_sent_seqcount 0 for stream 994 (in check_index_status() at live.cpp:1454)
1746:DBG1 - 17:26:56.083446379 [3866648/3866655]: Sending viewer index for stream 994 offset 0 (in viewer_get_next_index() at live.cpp:1801)
1748:DBG1 - 17:26:56.083544877 [3866648/3866655]: Index 1 for stream 994 sent (in viewer_get_next_index() at live.cpp:1842)
1751:DBG1 - 17:26:56.083778149 [3866648/3866655]: Sent 4108 bytes for stream 994 (in viewer_get_packet() at live.cpp:1968)
2858:DBG1 - 17:26:56.907744916 [3866648/3866652]: stream_add_index for stream 994 (in stream_add_index() at stream.cpp:1233)
2859:DBG1 - 17:26:56.907762798 [3866648/3866652]: Received live beacon for stream 994 (in stream_add_index() at stream.cpp:1237)
2862:DBG3 - 17:26:56.907855597 [3866648/3866652]: Receiving data for stream id 994 seqnum 1, 0 bytes received, 84 bytes left to receive (in relay_process_data_receive_payload() at main.cpp:3583)
2863:DBG1 - 17:26:56.907950195 [3866648/3866652]: Wrote to stream 994: data_length = 84, padding_length = 0 (in stream_write() at stream.cpp:1113)
2864:DBG1 - 17:26:56.908002911 [3866648/3866652]: Wrote to stream 994: data_length = 0, padding_length = 4012 (in stream_write() at stream.cpp:1113)
2865:DBG1 - 17:26:56.908024312 [3866648/3866652]: handle_index_data: stream 994 net_seq_num 1 data offset 4096 (in stream_update_index() at stream.cpp:1140)
2866:DBG3 - 17:26:56.908043082 [3866648/3866652]: Finding index for stream id 994 and seq_num 1 (in relay_index_get_by_id_or_create() at index.cpp:112)
2867:DBG2 - 17:26:56.908061879 [3866648/3866652]: Creating relay index for stream id 994 and seqnum 1 (in relay_index_create() at index.cpp:34)
2868:DBG2 - 17:26:56.908082115 [3866648/3866652]: Adding relay index with stream id 994 and seqnum 1 (in relay_index_add_unique() at index.cpp:70)
2869:DBG2 - 17:26:56.908101275 [3866648/3866652]: Index found or created in HT for stream ID 994 and seqnum 1 (in relay_index_get_by_id_or_create() at index.cpp:144)
3011:DBG1 - 17:26:56.913436908 [3866648/3866655]: Check index status: index_received_seqcount 1 index_sent_seqcount 1 for stream 994 (in check_index_status() at live.cpp:1454)
3012:DBG1 - 17:26:56.913457688 [3866648/3866655]: Check index status: inactive with beacon, for stream 994 (in check_index_status() at live.cpp:1492)
3014:DBG1 - 17:26:56.913507164 [3866648/3866655]: Index 1 for stream 994 sent (in viewer_get_next_index() at live.cpp:1842)
3043:DBG1 - 17:26:56.914167206 [3866648/3866652]: stream_add_index for stream 994 (in stream_add_index() at stream.cpp:1233)
3044:DBG3 - 17:26:56.914186324 [3866648/3866652]: Finding index for stream id 994 and seq_num 1 (in relay_index_get_by_id_or_create() at index.cpp:112)
3045:DBG2 - 17:26:56.914205597 [3866648/3866652]: Index found or created in HT for stream ID 994 and seqnum 1 (in relay_index_get_by_id_or_create() at index.cpp:144)
3046:DBG2 - 17:26:56.914227502 [3866648/3866652]: Writing index for stream ID 994 and seq num 1 (in relay_index_try_flush() at index.cpp:275)
3047:DBG2 - 17:26:56.914299536 [3866648/3866652]: index put for stream id 994 and seqnum 1 refcount 1 (in relay_index_put() at index.cpp:237)
3587:DBG1 - 17:26:57.067977800 [3866648/3866652]: Set begin data pending flag to stream 994 (in relay_begin_data_pending() at main.cpp:2240)
3644:DBG1 - 17:26:57.070915787 [3866648/3866652]: Data pending for stream id 994: prev_data_seq 1, prev_index_seq 1, and last_seq 1 (in relay_data_pending() at main.cpp:2091)
3913:DBG1 - 17:26:57.093492259 [3866648/3866652]: try_rotate_stream_index: Stream 994 (rotate_at_packet_seq_num = 2, received_packet_seq_num = (value = 1, is_set = 1)) (in try_rotate_stream_index() at stream.cpp:482)
3914:DBG1 - 17:26:57.093525950 [3866648/3866652]: Rotating stream 994 index file (in try_rotate_stream_index() at stream.cpp:511)
3915:DBG1 - 17:26:57.093561064 [3866648/3866652]: try_rotate_stream_data: Stream 994 (rotate_at_index_packet_seq_num = 2, rotate_at_prev_data_net_seq = 1, prev_data_seq = 1) (in try_rotate_stream_data() at stream.cpp:357)
3916:DBG1 - 17:26:57.093591085 [3866648/3866652]: Rotating stream 994 data file with size 8192 (in stream_rotate_data_file() at stream.cpp:138)
3917:DBG1 - 17:26:57.093626697 [3866648/3866652]: stream_rotate_data_file: reset tracefile_size_current for stream 994 was 8192 (in stream_rotate_data_file() at stream.cpp:169)
3918:DBG1 - 17:26:57.093656578 [3866648/3866652]: Rotation completed for stream 994 (in stream_complete_rotation() at stream.cpp:66)
4238:DBG1 - 17:26:57.635064782 [3866648/3866652]: Trying to close stream 994 (in try_stream_close() at stream.cpp:883)
4239:DBG1 - 17:26:57.635098224 [3866648/3866652]: Succeeded in closing stream 994 (in try_stream_close() at stream.cpp:983)
4744:DBG1 - 17:26:57.741972785 [3866648/3866655]: Check index status: index_received_seqcount 2 index_sent_seqcount 1 for stream 994 (in check_index_status() at live.cpp:1454)
4745:DBG1 - 17:26:57.742030216 [3866648/3866655]: Sending viewer index for stream 994 offset 4096 (in viewer_get_next_index() at live.cpp:1801)
4747:DBG1 - 17:26:57.742088421 [3866648/3866655]: Index 2 for stream 994 sent (in viewer_get_next_index() at live.cpp:1842)
4750:DBG1 - 17:26:57.742197990 [3866648/3866655]: Sent 4108 bytes for stream 994 (in viewer_get_packet() at live.cpp:1968)
4755:DBG1 - 17:26:57.932525633 [3866648/3866655]: Releasing stream id 994 (in stream_release() at stream.cpp:778)
4756:DBG1 - 17:26:57.932555313 [3866648/3866655]: Rotation completed for stream 994 (in stream_complete_rotation() at stream.cpp:66)

Cause
=====

This log shows the following sequence:

   consumer-data                       consumer-live-timer                     relayd-main                     relayd-live               babeltrace

1) lttng_consumer_read_subbuffer
  2) get next subbuf
  3) write data packet to data socket
     (starting here the data packet is
     somewhere on the network)
  4) put next subbuf
  5) post_consume()
    6) consumer_stream_sync_metadata_index()
      7) wait for metadata
         8) consumer_stream_sync_metadata()
                                       9) check_stream()
                                       10) set missed_metadata_flush
      11) call send_live_beacon(()
        12) sample empty ring buffer
        13) read current timestamp
        14) send inactivity beacon (empty packet)
                                                                               15) receives a live beacon                                                     (@ 17:26:56.907762798)
      16) call consumer_stream_send_index()
         17) send packet index to relayd
                                                                               18) receives a data packet                                                     (@ 17:26:56.907855597)
                                                                                  (at this point the data
                                                                                   packet is received from the
                                                                                   network)
                                                                                                                                         19) ask for next index
                                                                                                               20) informs the live viewer of the live beacon (@ 17:26:56.913457688)
                                                                               21) receives an index packet                                                   (@ 17:26:56.914227502)
                                                                                                                                         22) ask for next index
                                                                                                               23) sends the packet to the viewer             (@ 17:26:57.742197990)
                                                                                                                                         24) observes time going
                                                                                                                                             backwards between the
                                                                                                                                             previous live beacon
                                                                                                                                             and the data packet.

The issue is caused by consumer_stream_sync_metadata_index which is
called after sending a data packet (therefore after having consumed a
data packet from the ring buffer). It invokes the send_live_beacon
callback before sending the index associated with the data packet that
was just sent.

However, this introduces a discrepancy between the live beacon
inactivity guarantees and the yet-to-be-sent packet index: the data
packet sent at [3] can be anywhere on the network, not even received by
the relay daemon, when the live beacon is sampling a now empty ring
buffer at [12], and thus sends a live inactivity beacon to the relay
daemon. Then, when the index is sent by consumer_stream_send_index
[16], its timestamp is in the past compared to the inactivity beacon
sent by send_live_beacon [11].

The purpose of the field "stream->indexes_in_flight" is to prevent
setting the inactivity timestamp in the relay stream when data is
missing for indexes that were received. This works because the indexes
are sent over the control socket, which is where the inactivity beacons
are also sent. It does not however prevent issues the other way around:
data sent prior to the inactivity beacon may or may not have reached
the relay daemon. It is therefore important to make sure that consuming
ring buffer data and sending that data's index vs sampling for an empty
ring buffer and sending an inactivity beacon are correctly ordered.

Solution
========

Send inactivity beacon after packet index.

Also document the purpose of sending an inactivity beacon in this
scenario.

Note
====

This issue is present since lttng-tools 2.7.0 (backported to 2.6.1),
where lttng_ustconsumer_read_subbuffer() invokes
consumer_flush_ust_index() prior to call consumer_stream_write_index().
It was introduced by commit 288bdb302a1 ("Fix: sessiond vs consumerd
push/get metadata deadlock").

Known drawbacks
===============

None.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ied43cc8229413b25e69b40ac218adad420f18797

2 years agoFix: relayd: ressource leaks on viewer_stream_create error
Mathieu Desnoyers [Fri, 19 Nov 2021 20:11:37 +0000 (15:11 -0500)] 
Fix: relayd: ressource leaks on viewer_stream_create error

Observed issue
==============

When facing failure to open viewer stream chunks in the context of "Fix:
relayd: failure to open chunk files concurrently with session clear",
we observe that the relay daemon triggers an assertion due to a
non-empty session hash table on cleanup.

Cause
=====

viewer_stream_create() does a stream_get(), but without any matching
stream_put() on error. This in turn holds a reference on the ctf_trace,
which holds a reference on the session.

By inspecting the code, we notice that the following ressources can be
leaked on error:

- vstream->stream_file.handle,
- vstream->index_file,
- vstream->stream.

In non-error scenarios, viewer_stream_release() is responsible for
releasing references on the composite objects.

The vstream->stream_file.trace_chunk is not an issue because it is put
in the destroy handler (as well as within the release, before having its
vstream->stream_file.trace_chunk pointer set to NULL).

Solution
========

Properly put references on all objects which are contained by the viewer
stream on error by introducing
viewer_stream_release_composite_objects(), which is used both in the
error path of viewer_stream_create() and in viewer_stream_release().

Note
====

Why not move those "put" operations in viewer_stream_destroy ?

This is done in the release to ensure we put references on composite
objects immediately when our own reference reaches 0, rather than
waiting for a grace period through call_rcu, which could then cause
chained call_rcu callbacks and require multiple invocation of
rcu_barrier on relayd exit to guarantee that all callbacks have been
executed and all ressources properly freed.

Known drawbacks
===============

None.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I864b58eda94ebda5e6faea45c922d4e814a15daa

2 years agoFix: relayd: live: erroneous message timestamp observed from live viewer
Mathieu Desnoyers [Fri, 19 Nov 2021 16:12:25 +0000 (11:12 -0500)] 
Fix: relayd: live: erroneous message timestamp observed from live viewer

Observed issue
==============

Another situation where erroneous message timestamp is observed by the
live viewer. Happens rarely (only two occurrences while running
ust_clear in stress-tests overnight on a 16-core machine).

Triggered with the following test:

  # Test ust streaming live clear with viewer with new metadata after clear
  # Parameters: tracing_active=0, clear_twice=1, buffer_type=pid

Babeltrace 2 error:

  11-19 06:21:02.571 488497 488497 E PLUGIN/SRC.CTF.LTTNG-LIVE handle_late_message@lttng-live.c:1206 [lttng-live] Invalid live stream state: have a late message that is not a packet discarded or event discarded message: late-msg-type=PACKET_BEGINNING
  11-19 06:21:02.578 488497 488497 E PLUGIN/SRC.CTF.LTTNG-LIVE next_stream_iterator_for_trace@lttng-live.c:1360 [lttng-live] Late message could not be handled correctly: lttng-live-msg-iter-addr=0x55b4cdee1590, stream-name="stream-1024", curr-msg-ts=1637302861380968303, last-msg-ts=1637302861472798701
  11-19 06:21:02.578 488497 488497 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1802 [lttng-live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
  11-19 06:21:02.579 488497 488497 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:866 Component input port message iterator's "next" method failed: iter-addr=0x55b4cdecfe30, iter-upstream-comp-name="lttng-live", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR

Cause
=====

viewer_get_next_index() does not protect its use of the session
ongoing_rotation state by any synchronization mechanism. It only takes
the stream lock, which is not used to protect changes to the ongoing
rotation state with respect to the chunk rename operation performed by
chunk creation at the beginning of the clear command.

Solution
========

Protect the use of the session ongoing rotation state and file open
operations by the session lock in viewer_get_next_index().

Known drawbacks
===============

I don't expect this to cause any real scalability concern considering
the fact that the relay daemon has only two threads, one to handle
session daemon commands, and the other to handle viewer commands.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I242942ac6bc7a9199a17cd9800fc461a397b8955

2 years agoFix: relayd: failure to open chunk files concurrently with session clear
Mathieu Desnoyers [Thu, 18 Nov 2021 20:22:39 +0000 (15:22 -0500)] 
Fix: relayd: failure to open chunk files concurrently with session clear

Observed issue
==============

When stress-testing ust clear with an active live viewer, we observe a
situation where the live viewer thread fails to open chunk files in
make_viewer_streams() when executed after the creation of the new trace
chunk at the beginning of the clear command:

  DBG3 - 16:19:50.923577790 [40834/40838]: Processing "RELAYD_CREATE_TRACE_CHUNK" command for socket 19 (in relay_process_control_command() at main.cpp:3262)
  DBG1 - 16:19:50.923577730 [40834/40841]: Relay viewer stream 225 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923600762 [40834/40838]: lttng_trace_chunk_rename_path from  to .tmp_old_chunk (in lttng_trace_chunk_rename_path_no_lock() at trace-chunk.cpp:759)
  DBG1 - 16:19:50.923627202 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_26" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923664685 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_26" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923706441 [40834/40841]: Relay viewer stream 226 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923727770 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_27" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923744686 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_27" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923773427 [40834/40841]: Relay viewer stream 227 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923803791 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_28" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923831589 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_28" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923865981 [40834/40841]: Relay viewer stream 228 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923889329 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/index/my_chan-0_29.idx" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923905142 [40834/40838]: Creating trace chunk: chunk_id = 1, creation time = 20211118-161950 (in lttng_trace_chunk_create() at trace-chunk.cpp:440)
  DBG1 - 16:19:50.923907984 [40834/40841]: Adding new file "ust/uid/0/64-bit/index/my_chan-0_29.idx" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923937804 [40834/40838]: Chunk name set to "20211118T161950+0000-1" (in lttng_trace_chunk_create() at trace-chunk.cpp:471)
  PERROR - 16:19:50.923984288 [40834/40841]: Failed to open fs handle to ust/uid/0/64-bit/index/my_chan-0_29.idx, open() returned: No such file or directory (in fd_tracker_open_fs_handle() at fd-tracker.cpp:548)
  DBG1 - 16:19:50.924050763 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_29" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.924074480 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_29" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  PERROR - 16:19:50.924094720 [40834/40841]: Failed to open fs handle to ust/uid/0/64-bit/my_chan-0_29, open() returned: No such file or directory (in fd_tracker_open_fs_handle() at fd-tracker.cpp:548)
  DBG1 - 16:19:50.924193679 [40834/40841]: Viewer connection closed with 23 (in thread_worker() at live.cpp:2542)
  DBG1 - 16:19:50.924227482 [40834/40838]: Attempting to publish trace chunk: sessiond {34038782-6f74-4b2d-801e-752cf3d8885e}, session_id = 7, chunk_id = 1 (in sessiond_trace_chunk_registry_publish_chunk() at sessiond-trace-chunks.cpp:385)
  DBG1 - 16:19:50.924312916 [40834/40838]: Reset communication state of relay connection (fd = 19) (in connection_reset_protocol_state() at connection.cpp:82)
  DBG3 - 16:19:50.924350200 [40834/40838]: Relayd worker thread polling... (in relay_thread_worker() at main.cpp:3833)
  DBG3 - 16:19:50.924365222 [40834/40841]: Relayd live viewer worker thread polling... (in thread_worker() at live.cpp:2456)
  DBG1 - 16:19:50.926718319 [40834/40838]: Done receiving control command header: fd = 19, cmd = 18, cmd_version = 0, payload size = 532 bytes (in relay_process_control_receive_header() at main.cpp:3422)
  DBG3 - 16:19:50.926755574 [40834/40838]: Relayd worker thread polling... (in relay_thread_worker() at main.cpp:3833)
  DBG1 - 16:19:50.926787638 [40834/40838]: Done receiving control command payload: fd = 19, payload size = 532 bytes (in relay_process_control_receive_payload() at main.cpp:3339)
  DBG3 - 16:19:50.926811247 [40834/40838]: Processing "RELAYD_ROTATE_STREAMS" command for socket 19 (in relay_process_control_command() at main.cpp:3258)

Cause
=====

This is caused by relay_create_trace_chunk() using
lttng_trace_chunk_rename_path() to move away each trace subdirectory
into the subdirectory .tmp_old_chunk, and making this the new top-level
chunk directory (temporarily). This is a temporary state which will be
resorbed on relay_close_trace_chunk(), moving back the top-level chunk
directory to its original place.

Attempts to open chunk files from the prior chunk may result in failures,
because the chunk lock protecting the chunk rename operation only
protects the chunk owned by the relay thread, not its copy(ies) owned by
the live viewer thread.

This intermediate state should _not_ be observed by the live viewer
thread. The session ongoing rotation state should prevent the live
viewer threads from observing this.

Solution
========

Set the ongoing rotation state in relay_create_trace_chunk() earlier:
before invoking lttng_trace_chunk_rename_path(). Also ensure that the
session ongoing rotation state is protected by the session lock.

On the live thread side, introduce use of the session ongoing rotation
state in viewer_get_new_streams() and viewer_attach_session() to
effectively skip creation of the viewer streams if a session has a
rotation ongoing.

Viewers are expected to deal with the LTTNG_VIEWER_NEW_STREAMS_NO_NEW
reply (or handle the fact that no streams are currently available) and
try again later.

Both Babeltrace 2.0 and Babeltrace 1.5 appear to handle those replies
correctly.

Known drawbacks
===============

None.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I3ad8d59dff2994bfb62efa02a620f3c0ffbb5e3b

2 years agoFix: relayd: live: metadata stream reference count < 0 assert
Mathieu Desnoyers [Wed, 17 Nov 2021 16:55:36 +0000 (11:55 -0500)] 
Fix: relayd: live: metadata stream reference count < 0 assert

Observed issue
==============

While running tests/regression/tools/clear/test_ust test in a loop we
eventually witness the following error:

The symptom on the Babeltrace side is a Connection reset by peer. This
is caused by a relayd abort after an assertion failure due to a
reference count being lower than 0.

Test case:

  # Test ust streaming live clear with viewer
  # Parameters: tracing_active=0, clear_twice=0, buffer_type=pid

Tools commit: https://review.lttng.org/c/lttng-tools/+/6754/1

Relay daemon assertion failure stack trace:

  (gdb) bt
  #0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
  #1  0x00007ffa2e850859 in __GI_abort () at abort.c:79
  #2  0x00007ffa2e850729 in __assert_fail_base (fmt=0x7ffa2e9e6588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x56221bdb96f4 "res >= 0",
      file=0x56221bdb97a0 "/root/virtenv/usr/include/urcu/ref.h", line=66, function=<optimized out>) at assert.c:92
  #3  0x00007ffa2e861f36 in __GI___assert_fail (assertion=assertion@entry=0x56221bdb96f4 "res >= 0", file=file@entry=0x56221bdb97a0 "/root/virtenv/usr/include/urcu/ref.h", line=line@entry=66,
      function=function@entry=0x56221bdbd638 <__PRETTY_FUNCTION__.7554> "urcu_ref_put") at assert.c:101
  #4  0x000056221bd6a1cc in urcu_ref_put (release=<optimized out>, ref=0x7ffa24008cb0) at /root/virtenv/usr/include/urcu/ref.h:66
  #5  viewer_stream_put (vstream=vstream@entry=0x7ffa24008cb0) at viewer-stream.c:279
  #6  0x000056221bd5e4c5 in viewer_get_metadata (conn=conn@entry=0x7ffa0c000fc0) at live.c:2211
  #7  0x000056221bd63778 in process_control (conn=0x7ffa0c000fc0, recv_hdr=0x7ffa297c5af0) at live.c:2376
  #8  thread_worker (data=<optimized out>) at live.c:2541
  #9  0x00007ffa2ea28609 in start_thread (arg=<optimized out>) at pthread_create.c:477
  #10 0x00007ffa2e94d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Babeltrace crash:

11-17 05:13:05.197 47007 47007 D PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_get_next_index@viewer-connection.c:1494 [live] Requesting next index for stream: cmd=GET_NEXT_INDEX, viewer-stream-id=3352
11-17 05:13:05.215 47007 47007 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_recv@viewer-connection.c:245 [live] Error receiving from Relay: Connection reset by peer.
11-17 05:13:05.215 47007 47007 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_get_next_index@viewer-connection.c:1522 [live] Error receiving get next index reply
11-17 05:13:05.215 47007 47007 D PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_iterator_next_msg_on_stream@lttng-live.c:1069 [live] Returning from advancing live stream iterator: status=LTTNG_LIVE_ITERATOR_STATUS_ERROR, stream-name="stream-3352", viewer-stream-id=3352
11-17 05:13:05.215 47007 47007 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1802 [live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
11-17 05:13:05.216 47007 47007 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:866 Component input port message iterator's "next" method failed: iter-addr=0x563b7dd07700, iter-upstream-comp-name="live", iter-upstream-comp-log-level=TRACE, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUT
PUT, iter-upstream-port-name="out", status=ERROR
11-17 05:13:05.216 47007 47007 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:446 [mux] Upstream iterator's next method returned an error: status=ERROR
11-17 05:13:05.216 47007 47007 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:989 [mux] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x563b7dd04740, muxer-upstream-msg-iter-wrap-addr=0x563b7dd0db30
11-17 05:13:05.216 47007 47007 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1417 [mux] Cannot get next message: comp-addr=0x563b7dd1a760, muxer-comp-addr=0x563b7dd1b930, muxer-msg-iter-addr=0x563b7dd04740, msg-iter-addr=0x563b7dd07590, status=ERROR
11-17 05:13:05.216 47007 47007 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:866 Component input port message iterator's "next" method failed: iter-addr=0x563b7dd07590, iter-upstream-comp-name="mux", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT,
 iter-upstream-port-name="out", status=ERROR
11-17 05:13:05.216 47007 47007 W LIB/GRAPH consume_graph_sink@graph.c:462 Component's "consume" method failed: status=ERROR, comp-addr=0x563b7dd06d20, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=1, comp-class-so-handle-addr=0x563b7dd051b0, comp-class-so-handle-path="/root/virtenv/usr/lib/babeltr
ace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
11-17 05:13:05.217 47007 47007 E CLI cmd_run@babeltrace2.c:2537 Graph failed to complete successfully

Cause
=====

Both relay and live threads can put the ownership reference on the
metadata viewer stream concurrently without synchronization, thus
leading to a reference count going lower than 0.

The viewer stream ownership design initially planned for being owned by
the live thread, thus allowing the live thread to put the ownership
reference as soon as the associated relay stream is observed as closed,
and the viewer stream is considered as hung up.

However, in the specific case of the metadata viewer stream, the
responsibility of closing the metadata viewer stream is shared between
the relay and live threads, because the viewers expect to observe a
LTTNG_VIEWER_NO_NEW_METADATA message before the metadata stream
hangs up (see comment in viewer_get_metadata()). Therefore, if
viewer_get_metadata() is done before the metadata stream is closed, the
viewer will receive the LTTNG_VIEWER_NO_NEW_METADATA message, and set
the no_new_metadata_notified state to true. It's then the relay thread's
relay_close_stream() which will invoke the ownership put. However,
the live thread may concurrently try to put the viewer stream ownership
as well from a subsequent viewer_get_metadata(), thus leading to a
reference count < 0.

Solution
========

Fix this by putting the ownership reference from the live viewer thread
rather than the relay thread. This can be done by tracking the state of
no_new_metadata_notified within the live viewer thread.

Known drawbacks
===============

This will postpone reclaim of the metadata viewer stream from the
relay stream close to the following viewer_get_metadata (after a
LTTNG_VIEWER_NO_NEW_METADATA message has been replied), which I don't
think is an issue.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I9783d3a8402dddaa364a7a69c0764eaf30c16fde

2 years agoUpdate version to v2.13.2 v2.13.2
Jérémie Galarneau [Fri, 17 Dec 2021 17:00:33 +0000 (12:00 -0500)] 
Update version to v2.13.2

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
2 years agoValidate channel context mismatch across UST applications
Mathieu Desnoyers [Wed, 24 Nov 2021 20:56:16 +0000 (15:56 -0500)] 
Validate channel context mismatch across UST applications

Observed issue
==============

Applications traced with LTTng-UST are expected to all provide the exact
same layout for their channel's context fields, else it leads to
corrupted traces. This is only enforced within LTTng-UST. There is
nothing in the session daemon that prevents this scenario, and it is
only observable when reading the corrupted trace.

This makes the entire trace unreadable from the point where it is
corrupted.

Cause
=====

Even though LTTng-UST sends the entire description of its context fields
along with the channel registration notification, there is no validation
of the context fields' content against the context fields present in the
ust registry.

Solution
========

Validate each registered UST channel context fields against the fields
present in the registry. Reject the application if there is a mismatch.

Known drawbacks
===============

None.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I8b49032bf4f766e549dfccfafdce8cddcbb2873f

2 years agoFix: relayd: compare viewer chunks by ID rather than address
Mathieu Desnoyers [Thu, 18 Nov 2021 15:37:29 +0000 (10:37 -0500)] 
Fix: relayd: compare viewer chunks by ID rather than address

Observed issue
==============

In "Fix: relayd: live: erroneous message timestamp observed from live
viewer", we observe that sometimes viewer streams unexpectedly end up
performing a viewer stream rotation at session destroy.

Cause
=====

This may happen in the following scenario:

  1) Relay stream A is rotated to NULL.

  2) viewer_get_next_index for viewer stream A:
  2.1) observes a NULL rstream->trace_chunk, updates the viewer session
       current trace chunk to NULL (viewer_session_set_trace_chunk_copy).
  2.2) "Transition the viewer stream into the latest trace chunk
       available." does not issue viewer_stream_rotate_to_trace_chunk, because
       the condition (rstream->completed_rotation_count ==
       vstream->last_seen_rotation_count + 1 && !rstream->trace_chunk)
       evaluates to "true", and thus the entire if () evaluates to false.

  3) check_index_status detects rstream->closed and
     index_received_seqcount == index_sent_seqcount, thus replying HUP to
     viewer, effectively releasing ownership of the viewer stream.

  4) viewer_get_next_index for viewer stream B (not rotated to NULL yet):
  4.1) observes a non-NULL rstream->trace_chunk, updates the viewer
       session current trace chunk to *a new copy* of the non-NULL
       rstream->trace_chunk (viewer_session_set_trace_chunk_copy).
  4.2) the comparison (conn->viewer_session->current_trace_chunk !=
       vstream->stream_file.trace_chunk) done by pointer don't match, because
       the viewer session current trace chunk is a new copy.

Therefore, due to those stream close scenarios where the viewer session
can go back and forth between NULL and _different copies_ of the relay
chunk, we cannot use a comparison of chunks by address on the viewer
chunks.

Solution
========

Compare the viewer stream chunks by ID rather than address.

Known drawbacks
===============

The comparison is probably slightly slower, but I don't expect this to
be significant.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I05e4f97f26b2659c007726cc29d3edafa17bdb98

2 years agoFix: relayd: live: erroneous message timestamp observed from live viewer
Mathieu Desnoyers [Tue, 16 Nov 2021 20:59:01 +0000 (15:59 -0500)] 
Fix: relayd: live: erroneous message timestamp observed from live viewer

Observed issue
==============

While running tests/regression/tools/clear/test_ust test in a loop we
eventually witness the following error:

  # Test ust basic streaming live with viewer
  # Parameters: tracing_active=0, clear_twice=0, buffer_type=uid
  ok 425 - Create session 6jbcTSKUG7s2RIp5 with uri:net://localhost and opts: --live
  ok 426 - Enable channel chan for session 6jbcTSKUG7s2RIp5
  ok 427 - Enable ust event tp:tptest for session 6jbcTSKUG7s2RIp5
  ok 428 - Start tracing for session 6jbcTSKUG7s2RIp5
  # Waiting for live trace at url: net://localhost
  ok 429 - Waiting for live trace at url: net://localhost
  # Waiting for live viewers on url: net://localhost
  ok 430 - Waiting for live viewers on url: net://localhost
  # Wait until viewer sees all 10 expected events
  ok 431 - Live viewer read 10 events, expect 10
  ok 432 - Destroy session 6jbcTSKUG7s2RIp5
  # Waiting for application to exit
  ok 433 - Wait for application to exit
  # Wait for viewer to exit
  10-28 22:07:37.935 764967 764967 E PLUGIN/SRC.CTF.LTTNG-LIVE next_stream_iterator_for_trace@lttng-live.c:1222 [lttng-live] Message's timestamp is less than lttng-live's message iterator's last returned timestamp: lttng-live-msg-iter-addr=0x55fe45d4977
  0, ts=1635458857116911882, last-msg-ts=1635458857123908033
  10-28 22:07:37.937 764967 764967 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1662 [lttng-live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
  10-28 22:07:37.937 764967 764967 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:861 Component input port message iterator's "next" method failed: iter-addr=0x55fe45d38c50, iter-upstream-comp-name="lttng-live", iter-upstream-comp-log-level=WARNING,
   iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
  10-28 22:07:37.937 764967 764967 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:452 [muxer] Upstream iterator's next method returned an error: status=ERROR
  10-28 22:07:37.938 764967 764967 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:986 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x55fe45d33640, muxer-upstream-msg-iter-wrap-addr=0x55fe45d3
  af20
  10-28 22:07:37.938 764967 764967 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1411 [muxer] Cannot get next message: comp-addr=0x55fe45d49cb0, muxer-comp-addr=0x55fe45d49d30, muxer-msg-iter-addr=0x55fe45d33640, msg-iter-addr=0x55fe45d38ae0, sta
  tus=ERROR
  10-28 22:07:37.938 764967 764967 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:861 Component input port message iterator's "next" method failed: iter-addr=0x55fe45d38ae0, iter-upstream-comp-name="muxer", iter-upstream-comp-log-level=WARNING, iter
  -upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
  10-28 22:07:37.938 764967 764967 W LIB/GRAPH consume_graph_sink@graph.c:469 Component's "consume" method failed: status=ERROR, comp-addr=0x55fe45d49550, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-c
  lass-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x55fe45d38460, comp-class-so-handle-path="/root/virtenv/usr/lib/babeltrace2/plugins/babeltrace-plugin-text.la", comp-input-port-count=1, comp-out
  put-port-count=0
  10-28 22:07:37.938 764967 764967 E CLI cmd_run@babeltrace2.c:2547 Graph failed to complete successfully

Cause
=====

When doing the rotation associated with a clear,
viewer_stream_sync_tracefile_array_tail aims at pushing forward the
index_sent_seqcount for sessions in tracefile rotation mode to the
oldest available seqcount (tail) for this stream. It does not take into
consideration that the current index_sent_seqcount may already be passed
that oldest available seqcount position, thus eventually re-emitting
trace data.

For sessions *not* in tracefile rotation mode (this is known because
`tracefile_array_get_seq_tail()` returns -1ULL), this function
erroneously resets the index_sent_seqcount to 0, thus also causing trace
data to be re-emitted.

Solution
========

Solve this by using the maximum between the current index_sent_seqcount
and the tracefile array tail position as new position in
viewer_stream_sync_tracefile_array_tail.

Notes
=====

This symptom is also observed without using the clear command, simply on
destroy with a live viewer attached. This is caused by another issue
(not addressed by this patch) which causes
viewer_stream_rotate_to_trace_chunk to be sometimes invoked when streams
are closed on destroy.

Known drawbacks
===============

None.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ifb877d6e2bd94831ddf93077eac3cc968945d6f7

2 years agoFix: relayd comm: improperly packed rotate streams command header
Jérémie Galarneau [Tue, 14 Dec 2021 19:52:24 +0000 (14:52 -0500)] 
Fix: relayd comm: improperly packed rotate streams command header

Observed issue
==============

The implicit rotation of a session performed during its destruction
fails on LTTng 2.12 (and upwards) with the following errors:
  Error: Relayd rotate streams replied error 152
  Error: Relayd rotate stream failed. Cleaning up relayd 2
  Error: Rotate channel failed
  Failed to find relay daemon socket: relayd_id = 2
  Error: Failed to perform a quiet rotation as part of the destruction of session "my_session": Rotation failure on consumer

Cause
=====

Error 152 matches the LTTNG_ERR_INVALID_PROTOCOL error, which implies
that the consumer daemon sent an unexpected command to the relay daemon.

It was determined that the RELAYD_ROTATE_STREAMS command header is not
properly packed since the LTTNG_PACKED annotation was omitted from its
`new_chunk_id` optional field. The documentation of LTTNG_OPTIONAL_COMM
duly indicates that this is required.

Without the use of LTTNG_PACKED, various lengths of padding (3 or 7
bytes) are inserted between new_chunk_id's `is_set` and `value` field to
align `value`, which results in an incorrect interpretation of the
command's arguments.

The relay daemon catches the protocol error when it is built in a
configuration that inserts 7 bytes of padding, while the consumer only
inserts three.

Solution
========

The solution proposed here is not perfect, see "Known drawbacks".

First, if we were to annotate the field, patched consumer daemons would
send unintelligible command headers to unpatched relay daemons. Leaving
it as is is the least of all evils, see "Known drawbacks" for more
details.

From the relay daemon end, we can easily anticipate the padding problem
by reading the `stream_count` field and use it to determine the expected
size of the payload.

The difference between the actual size of the payload and the expected
size allows us to determine the padding size and use the appropriate
declaration of the structure to interpret the command's arguments.

Known drawbacks
===============

While this fix causes the relay daemon to handle all improperly packed
command headers received from an unpatched consumer daemon, the reverse
is not completely true.

The following tables show which cases are known to work and which are
known to be broken when patched and unpatched versions of the relay
and consumer daemons are mixed, with the various alignment constraints.

Note that here:
  - 4 byte alignement implies "daemon running on an architecture on
    which uint64_t is aligned on an 4-byte boundary" (e.g. x86),
  - 8 byte alignement implies "daemon running on an architecture on
    which uint64_t is aligned on an 8-byte boundary" (e.g. x86-64).

Scenario 1 - Unpatched relay daemon and unpatched consumer daemon
 -----------------------------------------------------------------------------------
| Architecture alignment | 4 byte alignement consumerd | 8 byte alignment consumerd |
|------------------------|-----------------------------|----------------------------|
| 4 byte alignment relay |           Works             |           Fails            |
| 8 byte alignment relay |           Fails             |           Works            |
 -----------------------------------------------------------------------------------

Scenario 2 - Patched relay daemon and unpatched consumer daemon
 -----------------------------------------------------------------------------------
| Architecture alignment | 4 byte alignement consumerd | 8 byte alignment consumerd |
|------------------------|-----------------------------|----------------------------|
| 4 byte alignment relay |           Works             |           Works            |
| 8 byte alignment relay |           Works             |           Works            |
 -----------------------------------------------------------------------------------

Scenario 3 - Unpatched relay daemon and patched consumer daemon
 -----------------------------------------------------------------------------------
| Architecture alignment | 4 byte alignement consumerd | 8 byte alignment consumerd |
|------------------------|-----------------------------|----------------------------|
| 4 byte alignment relay |           Works             |           Fails            |
| 8 byte alignment relay |           Fails             |           Works            |
 -----------------------------------------------------------------------------------

Scenario 4 - Patched relay daemon and patched consumer daemon
 -----------------------------------------------------------------------------------
| Architecture alignment | 4 byte alignement consumerd | 8 byte alignment consumerd |
|------------------------|-----------------------------|----------------------------|
| 4 byte alignment relay |           Works             |           Works            |
| 8 byte alignment relay |           Works             |           Works            |
 -----------------------------------------------------------------------------------

Note that Scenarios 1 and 3 are the same since this fix doesn't
change the behaviour of the consumer daemon.

Also note that packing the `new_chunk_id` field would break the two
working cases of scenario 3 which are, in all likelyhood, the more
common cases.

A new command using a properly packed version of the command's header
could be implemented in future versions, but this presents no benefit as
part of this fix.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I3b822a9766ea5be51996a771a0d4a90efe29ce0b

This page took 0.069443 seconds and 4 git commands to generate.