LTTng » LTTng-tools

When I try to use the minimal program that is joined to this bug report, when the event is enabled, LTTng returns "Event already enabled with different loglevel" even if the event were not enable previously.

This program was working in a previous version of LTTng (~ the 30/04/2012, date of the other report using the minimal.c program)

Here is the lttng-sessiond log:

root@USBnux:/home/xaf/git/dev-update# lttng-sessiond -vvv
DEBUG3: Creating LTTng run directory: /var/run/lttng [in create_lttng_rundir() at main.c:4151]
DEBUG2: Kernel consumer err path: /var/run/lttng/kconsumerd/error [in main() at main.c:4394]
DEBUG2: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command [in main() at main.c:4396]
DEBUG1: Client socket path /var/run/lttng/client-lttng-sessiond [in main() at main.c:4443]
DEBUG1: Application socket path /var/run/lttng/apps-lttng-sessiond [in main() at main.c:4444]
DEBUG1: LTTng run directory path: /var/run/lttng [in main() at main.c:4445]
DEBUG2: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error [in main() at main.c:4454]
DEBUG2: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command [in main() at main.c:4456]
DEBUG2: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error [in main() at main.c:4465]
DEBUG2: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command [in main() at main.c:4467]
DEBUG3: Created hashtable size 4 at 0x92d0a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x92d340 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Creating consumer directory: /var/run/lttng/kconsumerd [in set_consumer_sockets() at main.c:4193]
DEBUG1: Modprobe successfully lttng-tracer [in modprobe_lttng_control() at modprobe.c:163]
DEBUG2: Kernel tracer version validated (major version 2) [in kernel_validate_version() at kernel.c:675]
DEBUG1: Modprobe successfully lttng-ftrace [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-kprobes [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-kretprobes [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-lib-ring-buffer [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-ring-buffer-client-discard [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-ring-buffer-client-overwrite [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-ring-buffer-metadata-client [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-ring-buffer-client-mmap-discard [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-ring-buffer-client-mmap-overwrite [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-ring-buffer-metadata-mmap-client [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-lttng [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-types [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-block [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-irq [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-kvm [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-sched [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-signal [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-statedump [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Modprobe successfully lttng-probe-timer [in modprobe_lttng_data() at modprobe.c:199]
DEBUG1: Kernel tracer fd 6 [in init_kernel_tracer() at main.c:1710]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd64 [in set_consumer_sockets() at main.c:4193]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd32 [in set_consumer_sockets() at main.c:4193]
DEBUG1: Signal handler set for SIGTERM, SIGPIPE and SIGINT [in set_signal_handler() at main.c:4285]
Warning: No tracing group detected
DEBUG1: epoll set max size is 1227919 [in compat_epoll_set_max_size() at compat-epoll.c:224]
DEBUG1: Thread manage kernel started [in thread_manage_kernel() at main.c:699]
DEBUG1: Updating kernel poll set [in update_kernel_poll() at main.c:572]
DEBUG1: Thread kernel polling on 2 fds [in thread_manage_kernel() at main.c:728]
DEBUG1: [thread] Manage application started [in thread_manage_apps() at main.c:1002]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: [thread] Manage application registration started [in thread_registration_apps() at main.c:1215]
DEBUG1: Notifying applications of session daemon state: 1 [in notify_ust_apps() at main.c:511]
DEBUG1: Got the wait shm fd 18 [in get_wait_shm() at shm.c:117]
DEBUG1: Futex wait update active 1 [in futex_wait_update() at futex.c:62]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1246]
DEBUG1: [thread] Dispatch UST command started [in thread_dispatch_ust_registration() at main.c:1147]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:73]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1157]
DEBUG1: [thread] Manage client started [in thread_manage_clients() at main.c:3680]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3712]
DEBUG1: UST registration received with pid:4322 ppid:4321 uid:0 gid:0 sock:19 name:minimal (version 2.0) [in thread_registration_apps() at main.c:1333]
DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:100]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1246]
DEBUG1: Futex n to 1 wait done [in futex_nto1_wait() at futex.c:87]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:73]
DEBUG1: Dispatching UST registration pid:4322 ppid:4321 uid:0 gid:0 sock:19 name:minimal (version 2.0) [in thread_dispatch_ust_registration() at main.c:1169]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1157]
DEBUG3: Created hashtable size 4 at 0x930490 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:4322 ppid:4321 uid:0 gid:0 sock:19 name:minimal (version 2.0) [in ust_app_register() at ust-app.c:1365]
DEBUG2: UST app PID 4322 is compatible with major version 2 (supporting <= 2) [in ust_app_validate_version() at ust-app.c:2701]
DEBUG1: Apps with sock 19 added to poll set [in thread_manage_apps() at main.c:1103]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3749]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3784]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:3162]
DEBUG2: Trying to find session by name xhp [in session_find_by_name() at session.c:126]
DEBUG3: mkdir() recursive /home/xaf/OPAL/minimal/xhp-20120620-160703 with mode 504 for uid 0 and gid 0 [in run_as_mkdir_recursive() at runas.c:339]
DEBUG1: Using run_as_clone [in run_as() at runas.c:323]
DEBUG1: Tracing session xhp created in /home/xaf/OPAL/minimal/xhp-20120620-160703 with ID 1 by UID 0 GID 0 [in session_create() at session.c:234]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3822]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:491]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3712]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3749]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3784]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:3162]
DEBUG1: Getting session xhp by name [in process_client_msg() at main.c:3219]
DEBUG2: Trying to find session by name xhp [in session_find_by_name() at session.c:126]
DEBUG1: Creating UST session [in create_ust_session() at main.c:1788]
DEBUG3: Created hashtable size 4 at 0x934b60 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x934e20 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x9350e0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: UST trace session create successful [in trace_ust_create_session() at trace-ust.c:119]
DEBUG3: mkdir() recursive /home/xaf/OPAL/minimal/xhp-20120620-160703/ust with mode 504 for uid 0 and gid 0 [in run_as_mkdir_recursive() at runas.c:339]
DEBUG1: Using run_as_clone [in run_as() at runas.c:323]
DEBUG1: Spawning consumerd [in spawn_consumerd() at main.c:1482]
DEBUG2: Consumer pid 4327 [in start_consumerd() at main.c:1653]
DEBUG2: Spawning consumer control thread [in start_consumerd() at main.c:1656]
DEBUG1: [thread] Manage consumer started [in thread_manage_consumer() at main.c:805]
DEBUG1: Using 64-bit UST consumer at: /usr/local/lib/lttng/libexec/lttng-consumerd [in spawn_consumerd() at main.c:1556]
DEBUG2: Receiving code from consumer err_sock [in thread_manage_consumer() at main.c:866]
DEBUG1: consumer command socket ready [in thread_manage_consumer() at main.c:885]
DEBUG1: Enabling channel xhpchan for session xhp [in cmd_enable_channel() at main.c:2202]
DEBUG2: Trace UST channel xhpchan not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:52]
DEBUG3: Created hashtable size 4 at 0x9367c0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x936a80 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST channel xhpchan created [in trace_ust_create_channel() at trace-ust.c:181]
DEBUG2: Channel xhpchan being created in UST global domain [in channel_ust_create() at channel.c:267]
DEBUG2: UST app adding channel xhpchan to global domain for session id 1 [in ust_app_create_channel_glb() at ust-app.c:1868]
DEBUG2: UST app pid: 4322 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:883]
DEBUG3: Created hashtable size 4 at 0x937da0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Shadow copy of session handle -1 [in shadow_copy_session() at ust-app.c:794]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:907]
DEBUG3: Created hashtable size 4 at 0x938e10 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x9390b0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel xhpchan allocated [in alloc_ust_app_channel() at ust-app.c:298]
DEBUG2: UST app shadow copy of channel xhpchan started [in shadow_copy_channel() at ust-app.c:734]
DEBUG3: UST app shadow copy of channel xhpchan done [in shadow_copy_channel() at ust-app.c:771]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1023]
DEBUG2: UST app channel xhpchan created successfully for pid:4322 and sock:19 [in create_ust_channel() at ust-app.c:621]
DEBUG2: UST app create channel xhpchan for PID 4322 completed [in create_ust_app_channel() at ust-app.c:1126]
DEBUG2: Channel xhpchan created successfully [in channel_ust_create() at channel.c:292]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3822]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:491]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3712]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3749]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3784]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:3162]
DEBUG1: Getting session xhp by name [in process_client_msg() at main.c:3219]
DEBUG2: Trying to find session by name xhp [in session_find_by_name() at session.c:126]
DEBUG2: Trace UST channel xhpchan found by name [in trace_ust_find_channel_by_name() at trace-ust.c:47]
DEBUG2: Trace UST event NOT found by name ust_xhp:xhploop [in trace_ust_find_event_by_name() at trace-ust.c:79]
DEBUG3: Created hashtable size 4 at 0x9395d0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST event ust_xhp:xhploop, loglevel (0,-1) created [in trace_ust_create_event() at trace-ust.c:260]
DEBUG1: Enable event ust_xhp:xhploop does not match existing event ust_xhp:xhploop with loglevel respectively of -1 and 0 [in event_ust_enable_tracepoint() at event.c:424]
DEBUG2: Trace destroy UST event ust_xhp:xhploop [in trace_ust_destroy_event() at trace-ust.c:391]
DEBUG1: Sending response (size: 16, retcode: Event already enabled with different loglevel) [in thread_manage_clients() at main.c:3822]
DEBUG1: PID 4322 unregistering with sock 19 [in ust_app_unregister() at ust-app.c:1395]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1023]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:491]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3712]
DEBUG3: Call RCU deleting app PID 4322 [in delete_ust_app_rcu() at ust-app.c:237]
DEBUG2: UST app pid 4322 deleted [in delete_ust_app() at ust-app.c:220]

And here is the minimal execution return:

xaf@USBnux:~/OPAL/minimal$ sudo ./minimal 
LTTng: traces will be saved at /home/xaf/OPAL/minimal/xhp-20120620-160703

Subbuffers : 8 * 4096
LTTng: error enabling event: Event already enabled with different loglevel