Project

General

Profile

Bug #809

save/load fails with remote sessions

Added by Julien Desfossez almost 6 years ago. Updated almost 6 years ago.

Status:
Resolved
Priority:
High
Assignee:
-
Target version:
Start date:
06/20/2014
Due date:
% Done:

100%

Estimated time:

Description

lttng create -U net://localhost bla
lttng enable-event -k sched_switch -s bla
lttng save bla
lttng start bla
lttng stop bla
lttng destroy bla
At this point, the new trace exists on the relay.

lttng load bla
lttng start bla
lttng stop bla
lttng destroy bla
At this point, no new trace has been created on the relay

When loading the session with see this log on the relay, but nothing else when we issue the start/stop/destroy :
DEBUG1 - 15:06:52.222029 [14575/14579]: Relay new connection received (in relay_thread_listener() at main.c:824)
DEBUG1 - 15:06:52.222098 [14575/14579]: Relay control connection accepted, socket 20 (in relay_thread_listener() at main.c:866)
DEBUG1 - 15:06:52.222162 [14575/14579]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:104)
DEBUG1 - 15:06:52.222176 [14575/14579]: Listener accepting connections (in relay_thread_listener() at main.c:806)
DEBUG1 - 15:06:52.222166 [14575/14577]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:90)
DEBUG1 - 15:06:52.222204 [14575/14577]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:75)
DEBUG1 - 15:06:52.222228 [14575/14577]: Dispatching request waiting on sock 20 (in relay_thread_dispatcher() at main.c:967)
DEBUG1 - 15:06:52.222259 [14575/14577]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:961)
DEBUG1 - 15:06:52.222283 [14575/14578]: Connection socket 20 added (in relay_thread_worker() at main.c:2513)
DEBUG3 - 15:06:52.222342 [14575/14578]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2460)
DEBUG1 - 15:06:52.222373 [14575/14578]: Version check done using protocol 2.5 (in relay_send_version() at main.c:1597)
DEBUG3 - 15:06:52.222384 [14575/14578]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2460)
DEBUG3 - 15:06:52.222409 [14575/14578]: Created hashtable size 4 at 0x7f80d0001ac0 of type 0 (in lttng_ht_new() at hashtable.c:127)
DEBUG1 - 15:06:52.222424 [14575/14578]: Created session 13 (in relay_create_session() at main.c:1112)
DEBUG3 - 15:06:52.222444 [14575/14578]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2460)
DEBUG1 - 15:06:52.222717 [14575/14579]: Relay new connection received (in relay_thread_listener() at main.c:824)
DEBUG1 - 15:06:52.222796 [14575/14579]: Relay data connection accepted, socket 21 (in relay_thread_listener() at main.c:860)
DEBUG1 - 15:06:52.222829 [14575/14579]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:104)
DEBUG1 - 15:06:52.222833 [14575/14577]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:90)
DEBUG1 - 15:06:52.222842 [14575/14579]: Listener accepting connections (in relay_thread_listener() at main.c:806)
DEBUG1 - 15:06:52.222857 [14575/14577]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:75)
DEBUG1 - 15:06:52.222895 [14575/14577]: Dispatching request waiting on sock 21 (in relay_thread_dispatcher() at main.c:967)
DEBUG1 - 15:06:52.222925 [14575/14577]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:961)
DEBUG1 - 15:06:52.222946 [14575/14578]: Connection socket 21 added (in relay_thread_worker() at main.c:2513)
DEBUG3 - 15:06:52.222999 [14575/14578]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2460)

On the sessiond/consumerd :
lttng load bla
DEBUG1 - 15:13:03.169155 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.170159 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.170617 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:03.171093 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.171425 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.171755 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.172233 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.172606 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:03.172999 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.173431 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.196953 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.197752 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.198063 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:03.198371 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.198593 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.198826 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.199135 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.199491 [19170/19275]: Processing client command 8 (in process_client_msg() at main.c:2726)
DEBUG2 - 15:13:03.199913 [19170/19275]: Trying to find session by name bla (in session_find_by_name() at session.c:169)
DEBUG3 - 15:13:03.200253 [19170/19275]: Created hashtable size 4 at 0x7f53a4003ea0 of type 1 (in lttng_ht_new() at hashtable.c:127)
DEBUG1 - 15:13:03.200588 [19170/19275]: Tracing session bla created with ID 1 by UID 1000 GID 1000 (in session_create() at session.c:276)
DEBUG2 - 15:13:03.200793 [19170/19275]: Trying to find session by name bla (in session_find_by_name() at session.c:169)
DEBUG3 - 15:13:03.201181 [19170/19275]: Created hashtable size 4 at 0x7f53a4009420 of type 1 (in lttng_ht_new() at hashtable.c:127)
DEBUG2 - 15:13:03.201403 [19170/19275]: Session bla created with no output (in cmd_create_session_uri() at cmd.c:2055)
DEBUG1 - 15:13:03.201602 [19170/19275]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:4082)
DEBUG1 - 15:13:03.201994 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.202340 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.204113 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.204764 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.205046 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:03.205329 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.205536 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.205772 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.206420 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.206880 [19170/19275]: Processing client command 21 (in process_client_msg() at main.c:2726)
DEBUG1 - 15:13:03.207040 [19170/19275]: Getting session bla by name (in process_client_msg() at main.c:2807)
DEBUG2 - 15:13:03.207190 [19170/19275]: Trying to find session by name bla (in session_find_by_name() at session.c:169)
DEBUG1 - 15:13:03.207436 [19170/19275]: Creating kernel session (in create_kernel_session() at main.c:2642)
DEBUG3 - 15:13:03.207731 [19170/19275]: Created hashtable size 4 at 0x7f53a400ece0 of type 1 (in lttng_ht_new() at hashtable.c:127)
DEBUG1 - 15:13:03.208063 [19170/19275]: Kernel session created (fd: 30) (in kernel_create_session() at kernel.c:109)
DEBUG3 - 15:13:03.208270 [19170/19275]: Copying tracing session consumer output in kernel session (in copy_session_consumer() at main.c:2537)
DEBUG3 - 15:13:03.208663 [19170/19275]: Created hashtable size 4 at 0x7f53a400f1c0 of type 1 (in lttng_ht_new() at hashtable.c:127)
DEBUG3 - 15:13:03.208790 [19170/19273]: [ht-thread] Polling on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:64)
DEBUG3 - 15:13:03.209140 [19170/19275]: Copy session consumer subdir /kernel (in copy_session_consumer() at main.c:2573)
DEBUG3 - 15:13:03.209523 [19170/19275]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 15:13:03.209852 [19170/19275]: Setting relayd for session bla (in cmd_setup_relayd() at cmd.c:727)
DEBUG1 - 15:13:03.210091 [19170/19275]: Receiving 2 URI from client ... (in process_client_msg() at main.c:3299)
DEBUG2 - 15:13:03.210428 [19170/19275]: Setting network URI to consumer (in add_uri_to_consumer() at cmd.c:439)
DEBUG3 - 15:13:03.210654 [19170/19275]: Consumer control URI set with port 5342 (in consumer_set_network_uri() at consumer.c:641)
DEBUG3 - 15:13:03.210930 [19170/19275]: Consumer set network uri subdir path sinkpad/bla-20140620-150530 (in consumer_set_network_uri() at consumer.c:701)
DEBUG3 - 15:13:03.211132 [19170/19275]: Append domain trace name to subdir sinkpad/bla-20140620-150530/kernel (in add_uri_to_consumer() at cmd.c:481)
DEBUG2 - 15:13:03.211321 [19170/19275]: Setting network URI to consumer (in add_uri_to_consumer() at cmd.c:439)
DEBUG3 - 15:13:03.211503 [19170/19275]: Consumer data URI set with port 5343 (in consumer_set_network_uri() at consumer.c:656)
DEBUG1 - 15:13:03.211725 [19170/19275]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:4082)
DEBUG1 - 15:13:03.212083 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.212296 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.214790 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.215453 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.215747 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:03.216069 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.216285 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.216499 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.216794 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.217127 [19170/19275]: Processing client command 5 (in process_client_msg() at main.c:2726)
DEBUG1 - 15:13:03.217342 [19170/19275]: Getting session bla by name (in process_client_msg() at main.c:2807)
DEBUG2 - 15:13:03.217532 [19170/19275]: Trying to find session by name bla (in session_find_by_name() at session.c:169)
DEBUG3 - 15:13:03.217762 [19170/19275]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 15:13:03.217960 [19170/19275]: Setting relayd for session bla (in cmd_setup_relayd() at cmd.c:727)
DEBUG3 - 15:13:03.218320 [19170/19275]: Relayd connect ... (in relayd_connect() at relayd.c:471)
DEBUG3 - 15:13:03.219938 [19170/19275]: Creating relayd stream socket from URI (in create_connect_relayd() at cmd.c:572)
DEBUG1 - 15:13:03.220180 [19170/19275]: Relayd version check for major.minor 2.5 (in relayd_version_check() at relayd.c:369)
DEBUG3 - 15:13:03.220739 [19170/19275]: Relayd sending command 5 of size 32 (in send_command() at relayd.c:81)
DEBUG3 - 15:13:03.220976 [19170/19275]: Relayd waiting for reply of size 8 (in recv_reply() at relayd.c:101)
DEBUG2 - 15:13:03.225076 [19170/19275]: Relayd version is compatible, using protocol version 2.5 (in relayd_version_check() at relayd.c:417)
DEBUG1 - 15:13:03.225533 [19170/19275]: Relayd create session (in relayd_create_session() at relayd.c:182)
DEBUG3 - 15:13:03.226054 [19170/19275]: Relayd sending command 2 of size 351 (in send_command() at relayd.c:81)
DEBUG3 - 15:13:03.226295 [19170/19275]: Relayd waiting for reply of size 12 (in recv_reply() at relayd.c:101)
DEBUG1 - 15:13:03.228260 [19170/19275]: Relayd session created with id 6 (in relayd_create_session() at relayd.c:220)
DEBUG3 - 15:13:03.228715 [19170/19275]: Sending relayd sock info to consumer on 35 (in consumer_send_relayd_socket() at consumer.c:999)
DEBUG1 - 15:13:03.229368 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG1 - 15:13:03.229882 [19283/19289]: Consumer adding relayd socket (idx: 3) (in consumer_add_relayd_socket() at consumer.c:3282)
DEBUG3 - 15:13:03.230486 [19170/19275]: Sending relayd socket file descriptor to consumer (in consumer_send_relayd_socket() at consumer.c:1005)
DEBUG1 - 15:13:03.231497 [19283/19289]: Consumer control socket created successfully with net idx 3 (fd: -1) (in consumer_add_relayd_socket() at consumer.c:3412)
DEBUG1 - 15:13:03.231965 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG2 - 15:13:03.232103 [19170/19275]: Consumer relayd socket sent (in consumer_send_relayd_socket() at consumer.c:1011)
DEBUG3 - 15:13:03.232557 [19170/19275]: Relayd closing socket 31 (in relayd_close() at relayd.c:502)
DEBUG3 - 15:13:03.232941 [19170/19275]: Relayd connect ... (in relayd_connect() at relayd.c:471)
DEBUG3 - 15:13:03.234109 [19170/19275]: Creating relayd data socket from URI (in create_connect_relayd() at cmd.c:581)
DEBUG3 - 15:13:03.234490 [19170/19275]: Sending relayd sock info to consumer on 35 (in consumer_send_relayd_socket() at consumer.c:999)
DEBUG1 - 15:13:03.235130 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG1 - 15:13:03.235668 [19283/19289]: Consumer adding relayd socket (idx: 3) (in consumer_add_relayd_socket() at consumer.c:3282)
DEBUG3 - 15:13:03.235912 [19170/19275]: Sending relayd socket file descriptor to consumer (in consumer_send_relayd_socket() at consumer.c:1005)
DEBUG1 - 15:13:03.236331 [19283/19289]: Consumer data socket created successfully with net idx 3 (fd: -1) (in consumer_add_relayd_socket() at consumer.c:3412)
DEBUG1 - 15:13:03.236548 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG2 - 15:13:03.236763 [19170/19275]: Consumer relayd socket sent (in consumer_send_relayd_socket() at consumer.c:1011)
DEBUG3 - 15:13:03.237115 [19170/19275]: Relayd closing socket 31 (in relayd_close() at relayd.c:502)
DEBUG1 - 15:13:03.237474 [19170/19275]: Enabling channel channel0 for session bla (in cmd_enable_channel() at cmd.c:915)
DEBUG1 - 15:13:03.237687 [19170/19275]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG3 - 15:13:03.237909 [19170/19275]: Kernel create channel channel0 with attr: 0, 262144, 4, 0, 200000, 0, 0 (in kernel_create_channel() at kernel.c:143)
DEBUG1 - 15:13:03.258238 [19170/19275]: Kernel channel channel0 created (fd: 31) (in kernel_create_channel() at kernel.c:165)
DEBUG1 - 15:13:03.258823 [19170/19275]: Kernel quiescent wait on 6 (in kernel_wait_quiescent() at kernel.c:432)
DEBUG1 - 15:13:03.259723 [19170/19281]: Updating kernel poll set (in update_kernel_poll() at main.c:775)
DEBUG1 - 15:13:03.406959 [19170/19275]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:4082)
DEBUG1 - 15:13:03.407141 [19170/19281]: Channel fd 31 added to kernel set (in update_kernel_poll() at main.c:793)
DEBUG1 - 15:13:03.408364 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.408395 [19170/19281]: Thread kernel polling on 3 fds (in thread_manage_kernel() at main.c:960)
DEBUG1 - 15:13:03.408812 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.409282 [19170/19281]: Updating kernel streams for channel fd 31 (in update_kernel_stream() at main.c:819)
DEBUG1 - 15:13:03.409950 [19170/19281]: Channel found, updating kernel streams (in update_kernel_stream() at main.c:832)
DEBUG1 - 15:13:03.410322 [19170/19281]: Kernel stream channel0_0 created (fd: 29, state: 0) (in kernel_open_channel_stream() at kernel.c:565)
DEBUG1 - 15:13:03.410589 [19170/19281]: Kernel stream channel0_1 created (fd: 32, state: 0) (in kernel_open_channel_stream() at kernel.c:565)
DEBUG1 - 15:13:03.410858 [19170/19281]: Kernel stream channel0_2 created (fd: 37, state: 0) (in kernel_open_channel_stream() at kernel.c:565)
DEBUG1 - 15:13:03.411102 [19170/19281]: Kernel stream channel0_3 created (fd: 38, state: 0) (in kernel_open_channel_stream() at kernel.c:565)
DEBUG1 - 15:13:03.411320 [19170/19281]: Thread kernel polling on 3 fds (in thread_manage_kernel() at main.c:960)
DEBUG1 - 15:13:03.412166 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.412675 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.412930 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:03.413242 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.413448 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:03.413662 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:03.413960 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:03.414292 [19170/19275]: Processing client command 6 (in process_client_msg() at main.c:2726)
DEBUG1 - 15:13:03.414511 [19170/19275]: Getting session bla by name (in process_client_msg() at main.c:2807)
DEBUG2 - 15:13:03.414704 [19170/19275]: Trying to find session by name bla (in session_find_by_name() at session.c:169)
DEBUG3 - 15:13:03.414955 [19170/19275]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 15:13:03.415161 [19170/19275]: Setting relayd for session bla (in cmd_setup_relayd() at cmd.c:727)
DEBUG1 - 15:13:03.415387 [19170/19275]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 15:13:03.415587 [19170/19275]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 15:13:03.415776 [19170/19275]: Trying to find channel channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:48)
DEBUG1 - 15:13:03.415960 [19170/19275]: Found channel by name channel0 (in trace_kernel_get_channel_by_name() at trace-kernel.c:52)
DEBUG1 - 15:13:03.417788 [19170/19275]: Event sched_switch created (fd: 40) (in kernel_create_event() at kernel.c:239)
DEBUG1 - 15:13:03.418086 [19170/19275]: Kernel quiescent wait on 6 (in kernel_wait_quiescent() at kernel.c:432)
DEBUG1 - 15:13:03.567060 [19170/19275]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:4082)
DEBUG1 - 15:13:03.568238 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:03.568636 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)

lttng start bla
DEBUG1 - 15:13:08.631057 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:08.632073 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:08.632544 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:08.633048 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:08.633414 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:08.633783 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:08.634259 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:08.634530 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:08.634815 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:08.635035 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:08.635256 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:08.635568 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:08.635806 [19170/19275]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4037)
DEBUG1 - 15:13:08.636063 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:08.636265 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)
DEBUG1 - 15:13:08.636475 [19170/19275]: Wait for client response (in thread_manage_clients() at main.c:3988)
DEBUG1 - 15:13:08.636781 [19170/19275]: Receiving data from client ... (in thread_manage_clients() at main.c:4033)
DEBUG1 - 15:13:08.637139 [19170/19275]: Processing client command 16 (in process_client_msg() at main.c:2726)
DEBUG1 - 15:13:08.637440 [19170/19275]: Getting session bla by name (in process_client_msg() at main.c:2807)
DEBUG2 - 15:13:08.637655 [19170/19275]: Trying to find session by name bla (in session_find_by_name() at session.c:169)
DEBUG1 - 15:13:08.637914 [19170/19275]: Sending session stream to kernel consumer (in kernel_consumer_send_session() at kernel-consumer.c:374)
DEBUG1 - 15:13:08.638118 [19170/19275]: Sending streams of channel channel0 to kernel consumer (in kernel_consumer_send_channel_stream() at kernel-consumer.c:324)
DEBUG1 - 15:13:08.638321 [19170/19275]: Kernel consumer adding channel channel0 to kernel consumer (in kernel_consumer_add_channel() at kernel-consumer.c:98)
DEBUG1 - 15:13:08.638872 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG1 - 15:13:08.639623 [19283/19289]: consumer_add_channel 31 (in lttng_kconsumer_recv_cmd() at kernel-consumer.c:479)
DEBUG1 - 15:13:08.639713 [19170/19275]: Sending stream 38 of channel channel0 to kernel consumer (in kernel_consumer_add_stream() at kernel-consumer.c:241)
DEBUG1 - 15:13:08.640198 [19283/19289]: Allocated channel (key 31) (in consumer_allocate_channel() at consumer.c:1000)
DEBUG1 - 15:13:08.640626 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG1 - 15:13:08.640883 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG1 - 15:13:08.641869 [19170/19275]: Sending stream 37 of channel channel0 to kernel consumer (in kernel_consumer_add_stream() at kernel-consumer.c:241)
DEBUG3 - 15:13:08.641921 [19283/19289]: Allocated stream channel0_3 (key 31, chan_key 31 relayd_id 3, session_id 1 (in consumer_allocate_stream() at consumer.c:595)
DEBUG1 - 15:13:08.642616 [19283/19289]: Kernel consumer add stream channel0_3 in no monitor mode with relayd id 3 (in lttng_kconsumer_recv_cmd() at kernel-consumer.c:694)
DEBUG1 - 15:13:08.642877 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG1 - 15:13:08.643098 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG3 - 15:13:08.643959 [19283/19289]: Allocated stream channel0_2 (key 32, chan_key 31 relayd_id 3, session_id 1 (in consumer_allocate_stream() at consumer.c:595)
DEBUG1 - 15:13:08.643966 [19170/19275]: Sending stream 32 of channel channel0 to kernel consumer (in kernel_consumer_add_stream() at kernel-consumer.c:241)
DEBUG1 - 15:13:08.644361 [19283/19289]: Kernel consumer add stream channel0_2 in no monitor mode with relayd id 3 (in lttng_kconsumer_recv_cmd() at kernel-consumer.c:694)
DEBUG1 - 15:13:08.644691 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG1 - 15:13:08.645004 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG3 - 15:13:08.645733 [19283/19289]: Allocated stream channel0_1 (key 33, chan_key 31 relayd_id 3, session_id 1 (in consumer_allocate_stream() at consumer.c:595)
DEBUG1 - 15:13:08.645782 [19170/19275]: Sending stream 29 of channel channel0 to kernel consumer (in kernel_consumer_add_stream() at kernel-consumer.c:241)
DEBUG1 - 15:13:08.646341 [19283/19289]: Kernel consumer add stream channel0_1 in no monitor mode with relayd id 3 (in lttng_kconsumer_recv_cmd() at kernel-consumer.c:694)
DEBUG1 - 15:13:08.646670 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG1 - 15:13:08.646929 [19283/19289]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3101)
DEBUG3 - 15:13:08.647764 [19283/19289]: Allocated stream channel0_0 (key 34, chan_key 31 relayd_id 3, session_id 1 (in consumer_allocate_stream() at consumer.c:595)
DEBUG1 - 15:13:08.647791 [19170/19275]: Kernel consumer FDs of metadata and channel streams sent (in kernel_consumer_send_session() at kernel-consumer.c:402)
DEBUG1 - 15:13:08.648159 [19283/19289]: Kernel consumer add stream channel0_0 in no monitor mode with relayd id 3 (in lttng_kconsumer_recv_cmd() at kernel-consumer.c:694)
DEBUG1 - 15:13:08.648538 [19283/19289]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3117)
DEBUG1 - 15:13:08.144793 [19170/19275]: Kernel session started (in kernel_start_session() at kernel.c:417)
DEBUG1 - 15:13:08.144856 [19170/19275]: Kernel quiescent wait on 6 (in kernel_wait_quiescent() at kernel.c:432)
DEBUG1 - 15:13:08.164686 [19170/19275]: Sending response (size: 16, retcode: Success) (in thread_manage_clients() at main.c:4082)
DEBUG1 - 15:13:08.164787 [19170/19275]: Clean command context structure (in clean_command_ctx() at main.c:694)
DEBUG1 - 15:13:08.164832 [19170/19275]: Accepting client command ... (in thread_manage_clients() at main.c:3946)

#1

Updated by David Goulet almost 6 years ago

  • Status changed from New to Confirmed

It appears that the stream are added in no monitor mode which is NOT correct at all for a valid streaming session.

#2

Updated by David Goulet almost 6 years ago

  • Priority changed from Normal to High
  • Target version changed from 2.5 to 2.3

This is a much broader bug which is in the create session command. Setting the control and data URL makes the session in no output mode which is not switched back on even after a set consumer URL thus having stream created in no monitor. This can be reproduced with:

# lttng create -D tcp://localhost -C tcp://localhost
# lttng enable-event -a -k
# lttng start

This will fail to stream correctly since the trace is in no monitor because of the -C/-D. This goes back to 2.3!

#3

Updated by David Goulet almost 6 years ago

I'm about to push a commit that fixes this issue but only the no monitor mode part.

There is an other problem which for it I opened bug #813.

#4

Updated by David Goulet almost 6 years ago

  • Status changed from Confirmed to Resolved
  • % Done changed from 0 to 100

Applied in changeset tools|commit:7ab70fe08ac9308e320d58a672feab0282c11d47.

Also available in: Atom PDF