Project

General

Profile

Actions
Copy link

Bug #958

closed

lttng-ust, lttng-tools sensitive to /usr/local/lib

Added by Daniel U. Thibault about 9 years ago. Updated almost 9 years ago.

Status:
Resolved
Priority:
Low
Assignee:
-
Target version:
LTTng - 2.8
Start date:
10/21/2015
Due date:
% Done:

0%

Estimated time:

Description

On CentOS 7 (and, if I remember correctly, on Ubuntu as well), compiling lttng-ust and lttng-tools (2.7.0-stable) using the minimal sequence of commands will appear to work, but the tracer will then fail in an obscure way.

Specifically, lttng-ust (and lttng-tools) are compiled using:

# ./bootstrap &> bootstrap.log
# ./configure &> configure.log
# make &> make.log
# make install &> install.log
# ldconfig

But then (tracing the kernel from root):

# lttng create first
Session first created.
Traces will be written in /root/lttng-traces/first-20151021-120300
# lttng enable-event -k -a
Error: Events: Kernel consumer start failed (channel channel0, session first)
Error: Command error

It is only if we run 'lttng-sessiond -vvv' that we find out why:

# lttng enable-event -k sched_switch
DEBUG1 - 13:51:26.198860 [30037/30096]: Wait for client response (in thread_manage_clients() at main.c:4362)
DEBUG1 - 13:51:26.198954 [30037/30096]: Receiving data from client ... (in thread_manage_clients() at main.c:4407)
DEBUG1 - 13:51:26.198987 [30037/30096]: Processing client command 6 (in process_client_msg() at main.c:2989)
DEBUG1 - 13:51:26.199003 [30037/30096]: Getting session second by name (in process_client_msg() at main.c:3076)
DEBUG2 - 13:51:26.199013 [30037/30096]: Trying to find session by name first (in session_find_by_name() at session.c:172)
DEBUG1 - 13:51:26.199025 [30037/30096]: Creating kernel session (in create_kernel_session() at main.c:2905)
DEBUG3 - 13:51:26.199092 [30037/30096]: Created hashtable size 4 at 0x7f0854003d30 of type 1 (in lttng_ht_new() at hashtable.c:136)
DEBUG1 - 13:51:26.199200 [30037/30096]: Kernel session created (fd: 34) (in kernel_create_session() at kernel.c:106)
DEBUG3 - 13:51:26.199217 [30037/30096]: Copying tracing session consumer output in kernel session (in copy_session_consumer() at main.c:2787)
DEBUG3 - 13:51:26.199281 [30037/30096]: Created hashtable size 4 at 0x7f08540040f0 of type 1 (in lttng_ht_new() at hashtable.c:136)
DEBUG3 - 13:51:26.199308 [30037/30096]: Copy session consumer subdir /kernel (in copy_session_consumer() at main.c:2825)
DEBUG3 - 13:51:26.199318 [30037/30096]: mkdir() recursive /root/lttng-traces/first-20151021-120300 with mode 504 for uid 0 and gid 0 (in run_as_mkdir_recursive() at runas.c:468)
DEBUG1 - 13:51:26.199348 [30037/30096]: Using run_as worker (in run_as() at runas.c:449)
DEBUG3 - 13:51:26.199414 [30037/30039]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:74)
DEBUG3 - 13:51:26.199459 [30037/30039]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:67)
DEBUG1 - 13:51:26.200843 [30037/30096]: Spawning consumerd (in spawn_consumerd() at main.c:2494)
DEBUG2 - 13:51:26.201505 [30037/30096]: Consumer pid 30117 (in start_consumerd() at main.c:2679)
DEBUG2 - 13:51:26.201562 [30037/30096]: Spawning consumer control thread (in start_consumerd() at main.c:2682)
DEBUG3 - 13:51:26.203120 [30117/30117]: Looking for a kernel consumer at these locations: (in spawn_consumerd() at main.c:2516)
DEBUG3 - 13:51:26.203198 [30117/30117]:     1) /usr/local/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2517)
DEBUG3 - 13:51:26.203209 [30117/30117]:     2) /usr/local/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2518)
DEBUG3 - 13:51:26.203221 [30117/30117]:     3)  (in spawn_consumerd() at main.c:2519)
DEBUG3 - 13:51:26.203549 [30117/30117]: Found location #1 (in spawn_consumerd() at main.c:2521)
DEBUG1 - 13:51:26.203562 [30117/30117]: Using kernel consumer at: /usr/local/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2534)
lttng-consumerd: error while loading shared libraries: liburcu-common.so.4: cannot open shared object file: No such file or directory
DEBUG1 - 13:51:26.229367 [30037/30118]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1249)
Error: Condition timed out. The consumer thread was never ready. Killing it
Error: Fatal error spawning consumer control thread
DEBUG1 - 13:51:56.203692 [30037/30096]: Sending response (size: 16, retcode: Kernel consumer start failed) (in thread_manage_clients() at main.c:4456)
DEBUG1 - 13:51:56.203767 [30037/30096]: Clean command context structure (in clean_command_ctx() at main.c:829)
DEBUG1 - 13:51:56.203781 [30037/30096]: Accepting client command ... (in thread_manage_clients() at main.c:4310)

It turns out we needed to compile lttng-ust and lttng-tools using:

# ./bootstrap &> bootstrap.log
# LDFLAGS=-L/usr/local/lib ./configure &> configure.log
# make &> make.log
# make install &> install.log
# ldconfig

What is odd here is that the failure to spawn the consumer is not accompanied by a similar failure to launch other components (such as lttng-sessiond) that also depend on liburcu-common.so (and liburcu.so, etc.).

Actions
Copy link
 #1

Updated by Daniel U. Thibault about 9 years ago

Oops, sorry, this bug should be under LTTng Tools and LTTng UST.

Actions
Copy link
 #2

Updated by Jonathan Rajotte Julien about 9 years ago

  • Project changed from Babeltrace to LTTng-tools
  • Status changed from New to Feedback
  • Priority changed from Normal to Low

Hi Daniel,

The default location for userspace-rcu installation is quite clear in the ./configure --help (/usr/local). This installation directory is the default for both libs and bins across all lttng/userspace-rcu/babeltrace tools.

AFAIK most if not all of path with semi-hardcoded path to /usr/local (e.g consumerd) can be modified at configure time.

I was not able to reproduce on a fresh (really fresh) install on Ubuntu 14.04.[1]

I used https://github.com/psrcode/lttng-stack for the installation with master and stable 2.7 (lttng-tools and lttng-ust).I get the same output for both.
Indeed it is odd but I'm not sure it's related to lttng.

Cheers!

Jonathan

[1]

root@trusty:~/lttng-stack# lttng enable-event -k sched_switch
DEBUG1 - 17:52:58.604108 [20059/20167]: Wait for client response (in thread_manage_clients() at main.c:4398)
DEBUG1 - 17:52:58.604564 [20059/20167]: Receiving data from client ... (in thread_manage_clients() at main.c:4443)
DEBUG1 - 17:52:58.604740 [20059/20167]: Processing client command 6 (in process_client_msg() at main.c:2997)
DEBUG1 - 17:52:58.604875 [20059/20167]: Getting session auto-20151030-175235 by name (in process_client_msg() at main.c:3084)
DEBUG2 - 17:52:58.605167 [20059/20167]: Trying to find session by name auto-20151030-175235 (in session_find_by_name() at session.c:171)
DEBUG1 - 17:52:58.605340 [20059/20167]: Creating kernel session (in create_kernel_session() at main.c:2913)
DEBUG3 - 17:52:58.605552 [20059/20167]: Created hashtable size 4 at 0x7f34d4003d30 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 17:52:58.605853 [20059/20167]: Kernel session created (fd: 34) (in kernel_create_session() at kernel.c:105)
DEBUG3 - 17:52:58.605962 [20059/20167]: Copying tracing session consumer output in kernel session (in copy_session_consumer() at main.c:2795)
DEBUG3 - 17:52:58.606281 [20059/20167]: Created hashtable size 4 at 0x7f34d4004270 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 17:52:58.606345 [20059/20061]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:73)
DEBUG3 - 17:52:58.606593 [20059/20061]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:66)
DEBUG3 - 17:52:58.606394 [20059/20167]: Copy session consumer subdir /kernel (in copy_session_consumer() at main.c:2833)
DEBUG3 - 17:52:58.606994 [20059/20167]: mkdir() recursive /root/lttng-traces/auto-20151030-175235 with mode 504 for uid 0 and gid 0 (in run_as_mkdir_recursive() at runas.c:469)
DEBUG1 - 17:52:58.607148 [20059/20167]: Using run_as worker (in run_as() at runas.c:450)
DEBUG1 - 17:52:58.608115 [20059/20167]: Spawning consumerd (in spawn_consumerd() at main.c:2502)
DEBUG2 - 17:52:58.610135 [20059/20167]: Consumer pid 20191 (in start_consumerd() at main.c:2687)
DEBUG2 - 17:52:58.610535 [20059/20167]: Spawning consumer control thread (in start_consumerd() at main.c:2690)
DEBUG1 - 17:52:58.611490 [20059/20192]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1251)
DEBUG3 - 17:52:58.615206 [20191/20191]: Looking for a kernel consumer at these locations: (in spawn_consumerd() at main.c:2524)
DEBUG3 - 17:52:58.615283 [20191/20191]:     1) /usr/local/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2525)
DEBUG3 - 17:52:58.615306 [20191/20191]:     2) /usr/local/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2526)
DEBUG3 - 17:52:58.615316 [20191/20191]:     3)  (in spawn_consumerd() at main.c:2527)
DEBUG3 - 17:52:58.615406 [20191/20191]: Found location #1 (in spawn_consumerd() at main.c:2529)
DEBUG1 - 17:52:58.615425 [20191/20191]: Using kernel consumer at: /usr/local/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2542)
DEBUG2 - 17:52:58.618260 [20059/20192]: Receiving code from consumer err_sock (in thread_manage_consumer() at main.c:1349)
Warning: No tracing group detected
DEBUG1 - 17:52:58.719724 [20059/20192]: Consumer command socket ready (fd: 37 (in thread_manage_consumer() at main.c:1383)
DEBUG1 - 17:52:58.719807 [20059/20192]: Consumer metadata socket ready (fd: 38) (in thread_manage_consumer() at main.c:1385)
DEBUG3 - 17:52:58.719790 [20059/20167]: Consumer socket created (fd: 37) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 17:52:58.719851 [20059/20167]: Setting relayd for session auto-20151030-175235 (in cmd_setup_relayd() at cmd.c:764)
DEBUG1 - 17:52:58.719873 [20059/20167]: Enable event command for event 'sched_switch' (in _cmd_enable_event() at cmd.c:1537)
DEBUG1 - 17:52:58.719892 [20059/20167]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 17:52:58.719911 [20059/20167]: Enabling channel  for session auto-20151030-175235 (in cmd_enable_channel() at cmd.c:1059)
DEBUG1 - 17:52:58.719919 [20059/20167]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG3 - 17:52:58.719937 [20059/20167]: Kernel create channel  with attr: 0, 262144, 4, 0, 200000, 0, 0 (in kernel_create_channel() at kernel.c:139)
DEBUG1 - 17:52:58.725593 [20059/20167]: Kernel channel channel0 created (fd: 39) (in kernel_create_channel() at kernel.c:161)
DEBUG1 - 17:52:58.725646 [20059/20167]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:566)
DEBUG1 - 17:52:58.725707 [20059/20173]: Thread kernel return from poll on 2 fds (in thread_manage_kernel() at main.c:1129)
DEBUG1 - 17:52:58.729468 [20059/20173]: Updating kernel poll set (in update_kernel_poll() at main.c:912)
DEBUG1 - 17:52:58.740298 [20059/20167]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 17:52:58.740381 [20059/20167]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 17:52:58.740511 [20059/20167]: Event sched_switch created (fd: 40) (in kernel_create_event() at kernel.c:247)
DEBUG1 - 17:52:58.740540 [20059/20167]: Kernel quiescent wait on 13 (in kernel_wait_quiescent() at kernel.c:566)
DEBUG1 - 17:52:58.744338 [20059/20173]: Channel fd 39 added to kernel set (in update_kernel_poll() at main.c:930)
DEBUG1 - 17:52:58.744391 [20059/20173]: Thread kernel polling (in thread_manage_kernel() at main.c:1122)
DEBUG1 - 17:52:58.744409 [20059/20173]: Thread kernel return from poll on 3 fds (in thread_manage_kernel() at main.c:1129)
DEBUG1 - 17:52:58.744526 [20059/20173]: Updating kernel streams for channel fd 39 (in update_kernel_stream() at main.c:956)
DEBUG1 - 17:52:58.744536 [20059/20173]: Channel found, updating kernel streams (in update_kernel_stream() at main.c:975)
DEBUG1 - 17:52:58.744559 [20059/20173]: Kernel stream channel0_0 created (fd: 41, state: 0) (in kernel_open_channel_stream() at kernel.c:699)
DEBUG1 - 17:52:58.744577 [20059/20173]: Kernel stream channel0_1 created (fd: 42, state: 0) (in kernel_open_channel_stream() at kernel.c:699)
DEBUG1 - 17:52:58.744599 [20059/20173]: Kernel stream channel0_2 created (fd: 43, state: 0) (in kernel_open_channel_stream() at kernel.c:699)
DEBUG1 - 17:52:58.744611 [20059/20173]: Kernel stream channel0_3 created (fd: 44, state: 0) (in kernel_open_channel_stream() at kernel.c:699)
DEBUG1 - 17:52:58.744618 [20059/20173]: Thread kernel polling (in thread_manage_kernel() at main.c:1122)
DEBUG1 - 17:52:58.744706 [20059/20167]: Sending response (size: 16, retcode: Success (10)) (in thread_manage_clients() at main.c:4493)
Kernel event sched_switch created in channel channel0
DEBUG1 - 17:52:58.745404 [20059/20167]: Clean command context structure (in clean_command_ctx() at main.c:831)
DEBUG1 - 17:52:58.745435 [20059/20167]: Accepting client command ... (in thread_manage_clients() at main.c:4346)

Actions
Copy link
 #3

Updated by Jonathan Rajotte Julien almost 9 years ago

  • Status changed from Feedback to Invalid
Actions
Copy link
 #4

Updated by Jonathan Rajotte Julien almost 9 years ago

  • Status changed from Invalid to Resolved
Actions
Copy link

Also available in: Atom PDF