Project

General

Profile

Bug #404 » Activation_fails_when_event_is_enabled_wo_filter.txt

Jesus Garcia, 11/23/2012 10:15 AM

 
Session without filter, fails

SC-1:/storage/no-backup/coremw/var/log/saflog # date;ps -eaf | egrep "trace|lttng" | grep -v grep
Thu Nov 22 22:12:03 EST 2012
root 12781 1 0 22:07 ? 00:00:00 lttng-sessiond -d
root 12792 12781 0 22:07 ? 00:00:01 lttng-consumerd --quiet -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 23324 1 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 23332 23324 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 25334 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_c
root 25346 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_p
SC-1:/storage/no-backup/coremw/var/log/saflog # pkill -9 lttng-sessiond; usleep 100000; lttng-sessiond -vvv --verbose-consumer --no-kernel > /cluster/temp/eusgarc/sc1_sessiond.log 2>&1 &
[7] 14495
SC-1:/storage/no-backup/coremw/var/log/saflog # sleep 2
DEBUG3: Creating LTTng run directory: /var/run/lttng [in create_lttng_rundir() at main.c:3659]
DEBUG2: Kernel consumer err path: /var/run/lttng/kconsumerd/error [in main() at main.c:3907]
DEBUG2: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command [in main() at main.c:3909]
DEBUG1: Client socket path /var/run/lttng/client-lttng-sessiond [in main() at main.c:3962]
DEBUG1: Application socket path /var/run/lttng/apps-lttng-sessiond [in main() at main.c:3963]
DEBUG1: LTTng run directory path: /var/run/lttng [in main() at main.c:3964]
DEBUG2: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error [in main() at main.c:3973]
DEBUG2: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command [in main() at main.c:3975]
DEBUG2: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error [in main() at main.c:3984]
DEBUG2: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command [in main() at main.c:3986]
DEBUG3: Created hashtable size 4 at 0x6410a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x6415c0 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:3701]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd64 [in set_consumer_sockets() at main.c:3701]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd32 [in set_consumer_sockets() at main.c:3701]
DEBUG1: Signal handler set for SIGTERM, SIGPIPE and SIGINT [in set_signal_handler() at main.c:3793]
DEBUG3: Session daemon client socket 8 and application socket 9 created [in init_daemon_socket() at main.c:3563]
Warning: No tracing group detected
DEBUG1: epoll set max size is 403353 [in compat_epoll_set_max_size() at compat-epoll.c:224]
DEBUG1: Command subsystem initialized [in cmd_init() at cmd.c:2419]
DEBUG1: [thread] Manage health check started [in thread_manage_health() at main.c:2925]
DEBUG1: [thread] Manage client started [in thread_manage_clients() at main.c:3119]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2964]
DEBUG1: [thread] Dispatch UST command started [in thread_dispatch_ust_registration() at main.c:1283]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:75]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1293]
DEBUG1: [thread] Manage application started [in thread_manage_apps() at main.c:1094]
DEBUG1: [thread] Manage application registration started [in thread_registration_apps() at main.c:1359]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1123]
DEBUG1: Notifying applications of session daemon state: 1 [in notify_ust_apps() at main.c:496]
DEBUG1: Got the wait shm fd 17 [in get_wait_shm() at shm.c:117]
DEBUG1: Futex wait update active 1 [in futex_wait_update() at futex.c:63]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1392]
SC-1:/storage/no-backup/coremw/var/log/saflog # /cluster/temp/eusgarc/test_error
Thu Nov 22 22:12:06 EST 2012
root 14495 2028 0 22:12 pts/3 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 23324 1 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 23332 23324 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 25334 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_c
root 25346 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_p
Thu Nov 22 22:12:06 EST 2012
Creating Profile
####################
Thu Nov 22 22:12:06 EST 2012
Nov 22 22:12:06 SC-1 osafimmnd[6574]: Ccb 16241 COMMITTED (TraceCLI)
Nov 22 22:12:06 PL-4 osafimmnd[4925]: Ccb 16241 COMMITTED (TraceCLI)
Nov 22 22:12:06 PL-3 osafimmnd[4916]: Ccb 16241 COMMITTED (TraceCLI)
Nov 22 22:12:06 SC-2 osafimmnd[5125]: Ccb 16241 COMMITTED (TraceCLI)
Thu Nov 22 22:12:06 EST 2012
Wait 1 sec...
Nov 22 22:12:06 SC-1 osafimmnd[6574]: Ccb 16242 COMMITTED (TraceC)
Nov 22 22:12:06 PL-4 osafimmnd[4925]: Ccb 16242 COMMITTED (TraceC)
Nov 22 22:12:06 PL-3 osafimmnd[4916]: Ccb 16242 COMMITTED (TraceC)
Nov 22 22:12:06 SC-2 osafimmnd[5125]: Ccb 16242 COMMITTED (TraceC)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2180]
DEBUG1: Waiting for 1 URIs from client ... [in process_client_msg() at main.c:2687]
DEBUG2: Trying to find session by name /_TraceCValidator_II9akY [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session /_TraceCValidator_II9akY created in (null) with ID 0 by UID 0 GID 0 [in session_create() at session.c:236]
DEBUG2: Trying to find session by name /_TraceCValidator_II9akY [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x64cb90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting trace directory path from URI to /tmp/_TraceCValidator_II9akY [in add_uri_to_consumer() at cmd.c:407]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session /_TraceCValidator_II9akY by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name /_TraceCValidator_II9akY [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2067]
DEBUG3: Created hashtable size 4 at 0x645a00 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x645f40 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x646480 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x652130 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: UST trace session create successful [in trace_ust_create_session() at trace-ust.c:238]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2019]
DEBUG3: Created hashtable size 4 at 0x652130 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Copy session consumer subdir /ust [in copy_session_consumer() at main.c:2037]
DEBUG1: Spawning consumerd [in spawn_consumerd() at main.c:1700]
DEBUG2: Consumer pid 14514 [in start_consumerd() at main.c:1881]
DEBUG2: Spawning consumer control thread [in start_consumerd() at main.c:1884]
DEBUG1: [thread] Manage consumer started [in thread_manage_consumer() at main.c:844]
DEBUG1: Using 64-bit UST consumer at: /usr/lib64/lttng/libexec/lttng-consumerd [in spawn_consumerd() at main.c:1774]
DEBUG1: epoll set max size is 403353 [in compat_epoll_set_max_size() at compat-epoll.c:224]
DEBUG3: Created hashtable size 4 at 0x61f030 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x61f570 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x61fab0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x61fff0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x620530 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: Connecting to error socket /var/run/lttng/ustconsumerd64/error [in main() at lttng-consumerd.c:358]
DEBUG3: Created hashtable size 4 at 0x620ec0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: Creating command socket /var/run/lttng/ustconsumerd64/command [in consumer_thread_sessiond_poll() at consumer.c:2447]
DEBUG1: Thread metadata poll started [in consumer_thread_metadata_poll() at consumer.c:2000]
DEBUG1: Sending ready command to lttng-sessiond [in consumer_thread_sessiond_poll() at consumer.c:2460]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:901]
DEBUG1: Metadata main loop started [in consumer_thread_metadata_poll() at consumer.c:2015]
DEBUG1: Metadata poll wait with 1 fd(s) [in consumer_thread_metadata_poll() at conDEBUG3: ConsumDEBUG1: Connection on client_socket [in consumer_thread_sessiond_poll() at consumer.c:2483]
DEBUG1: polling on 1 fd [in consumer_thread_data_poll() at consumer.c:2249]
n cmd_enable_channel() at cmd.c:822]
DEBUG2: Trace UST channel channel0 not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:141]
DEBUG3: Created hashtable size 4 at 0x653ae0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x654020 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST channel channel0 created [in trace_ust_create_channel() at trace-ust.c:302]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:273]
DEBUG2: UST app adding channel channel0 to global domain for session id 0 [in ust_app_create_channel_glb() at ust-app.c:2011]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:298]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session /_TraceCValidator_II9akY by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name /_TraceCValidator_II9akY [in session_find_by_name() at session.c:122]
DEBUG3: No kernel session when tearing down session [in kernel_destroy_session() at kernel.c:701]
DEBUG1: Destroy all UST traces [in ust_app_destroy_trace_all() at ust-app.c:2531]
DEBUG2: Trace UST destroy session 0 [in trace_ust_destroy_session() at trace-ust.c:667]
DEBUG1: Destroying session /_TraceCValidator_II9akY [in session_destroy() at session.c:149]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG2: Trace destroy UST channel channel0 [in trace_ust_destroy_channel() at trace-ust.c:550]
64211 22:12:06 11/22/2012 IN TraceC "DBG: ProfileAdmin::profileIdValidator was called
64212 22:12:06 11/22/2012 IN TraceC "DBG: newvalue size=23
64213 22:12:06 11/22/2012 IN TraceC "DBG: newvalue=traceProfileId=TestProf

64214 22:12:06 11/22/2012 IN TraceC "DBG: ProfileAdmin::traceExpressionsValidator was called
64215 22:12:06 11/22/2012 IN TraceC "DBG: traceExpressions size=1
64216 22:12:06 11/22/2012 IN TraceC "DBG: About to create a temporary session /_TraceCValidator_II9akY in path /tmp/_TraceCValidator_II9akY
64217 22:12:06 11/22/2012 IN TraceC "DBG: Try to remove directory "/tmp/_TraceCValidator_II9akY"
64218 22:12:06 11/22/2012 IN TraceC "DBG: Remove Directory "/tmp/_TraceCValidator_II9akY" Deleted!
64219 22:12:06 11/22/2012 IN TraceC "DBG: Create: class: AsyncActionProgress, parentName: traceProfileId=TestProf,traceMId=1
Thu Nov 22 22:12:07 EST 2012
root 14495 2028 0 22:12 pts/3 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 14514 14495 0 22:12 pts/3 00:00:00 lttng-consumerd --verbose -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 23324 1 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 23332 23324 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 25334 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_c
root 25346 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_p
Thu Nov 22 22:12:07 EST 2012
Activating Profile
####################
Thu Nov 22 22:12:07 EST 2012
Nov 22 22:12:07 SC-1 osafimmnd[6574]: Ccb 16244 COMMITTED (TraceC)
Nov 22 22:12:07 PL-4 osafimmnd[4925]: Ccb 16244 COMMITTED (TraceC)
Nov 22 22:12:07 PL-3 osafimmnd[4916]: Ccb 16244 COMMITTED (TraceC)
Nov 22 22:12:07 SC-2 osafimmnd[5125]: Ccb 16244 COMMITTED (TraceC)
Nov 22 22:12:07 PL-4 osafimmnd[4925]: Ccb 16245 COMMITTED (TraceC)
Nov 22 22:12:07 SC-1 osafimmnd[6574]: Ccb 16245 COMMITTED (TraceC)
Nov 22 22:12:07 PL-3 osafimmnd[4916]: Ccb 16245 COMMITTED (TraceC)
Nov 22 22:12:07 SC-2 osafimmnd[5125]: Ccb 16245 COMMITTED (TraceC)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3250]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2180]
DEBUG1: Waiting for 1 URIs from client ... [in process_client_msg() at main.c:2687]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session _Trace_EA created in (null) with ID 1 by UID 0 GID 0 [in session_create() at session.c:236]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x653960 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting trace directory path from URI to /cluster/temp/eusgarc/deleteme/ [in add_uri_to_consumer() at cmd.c:407]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2067]
DEBUG3: Created hashtable size 4 at 0x653ea0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x6459e0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x645f20 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x646440 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: UST trace session create successful [in trace_ust_create_session() at trace-ust.c:238]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2019]
DEBUG3: Created hashtable size 4 at 0x646440 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Copy session consumer subdir /ust [in copy_session_consumer() at main.c:2037]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG1: Enabling channel channel0 for session _Trace_EA [in cmd_enable_channel() at cmd.c:822]
DEBUG2: Trace UST channel channel0 not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:141]
DEBUG3: Created hashtable size 4 at 0x651d00 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x652240 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST channel channel0 created [in trace_ust_create_channel() at trace-ust.c:302]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:273]
DEBUG2: UST app adding channel channel0 to global domain for session id 1 [in ust_app_create_channel_glb() at ust-app.c:2011]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:298]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG2: Trace UST channel channel0 found by name [in trace_ust_find_channel_by_name() at trace-ust.c:136]
DEBUG2: Trace UST event _TRACE_EA_FAKE_EVENT NOT found [in trace_ust_find_event() at trace-ust.c:174]
DEBUG2: Trace UST event _TRACE_EA_FAKE_EVENT, loglevel (0,-1) created [in trace_ust_create_event() at trace-ust.c:378]
DEBUG1: UST app creating event _TRACE_EA_FAKE_EVENT for all apps for session id 1 [in ust_app_create_event_glb() at ust-app.c:2136]
DEBUG1: Event UST _TRACE_EA_FAKE_EVENT created in channel channel0 [in event_ust_enable_tracepoint() at event.c:476]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 16 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG2: Setting relayd for session _Trace_EA [in setup_relayd() at cmd.c:643]
DEBUG1: Starting all UST traces [in ust_app_start_trace_all() at ust-app.c:2479]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 17 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG1: Stopping all UST traces [in ust_app_stop_trace_all() at ust-app.c:2505]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 33 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: Consumer data pending for id 1 [in consumer_is_data_pending() at consumer.c:725]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2505]
DEBUG1: UST consumer data pending command for id 1 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:318]
DEBUG1: Consumer data pending command on session id 1 [in consumer_data_pending() at consumer.c:2725]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2523]
DEBUG1: Consumer data pending ret 0 [in consumer_is_data_pending() at consumer.c:756]
DEBUG1: Sending response (size: 16, retcode: Unknown error code) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: No kernel session when tearing down session [in kernel_destroy_session() at kernel.c:701]
DEBUG1: Destroy all UST traces [in ust_app_destroy_trace_all() at ust-app.c:2531]
DEBUG2: Trace UST destroy session 1 [in trace_ust_destroy_session() at trace-ust.c:667]
DEBUG1: Destroying session _Trace_EA [in session_destroy() at session.c:149]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG2: Trace destroy UST channel channel0 [in trace_ust_destroy_channel() at trace-ust.c:550]
DEBUG2: Trace destroy UST event _TRACE_EA_FAKE_EVENT [in trace_ust_destroy_event() at trace-ust.c:509]
64220 22:12:07 11/22/2012 IN TraceC "DBG: Activating
64221 22:12:07 11/22/2012 IN TraceC "DBG: creating session traceSessionRecordingId=TestProf_1,traceMId=1 as a runtime object
64222 22:12:07 11/22/2012 NO TraceC "Activating Session TestProf_1.
64223 22:12:07 11/22/2012 IN TraceC "DBG: Directory /home/trace//TestProf_1 was created successfully!
64224 22:12:07 11/22/2012 IN TraceC "DBG: Return for invocation 1 value: 1, return code: 1 , SA_AIS_OK
64225 22:12:07 11/22/2012 IN TraceC "DBG: relayD ip address is found: 192.168.0.1
64226 22:12:07 11/22/2012 IN TraceC "DBG: RelayDManager::start() Control port selected: 52362
64227 22:12:07 11/22/2012 IN TraceC "DBG: RelayDManager::start() Data port selected: 50027
64228 22:12:07 11/22/2012 IN TraceC "DBG: RelayDManager::start() Pipe opened
64229 22:12:07 11/22/2012 IN TraceC "DBG: relayD ip address is found: 192.168.0.1
64230 22:12:07 11/22/2012 IN TraceC "DBG: RelayDManager::start() RelayD for "TestProf_1" pid: 14531 bound on 192.168.0.1:52362:50027
64231 22:12:07 11/22/2012 IN TraceC "DBG: Done Activating
64232 22:12:07 11/22/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestProf_1 is being added to parent directory /home/trace
64233 22:12:07 11/22/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
64234 22:12:07 11/22/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
DEBUG1: UST registration received with pid:11458 ppid:1 uid:0 gid:0 sock:17 name:TestApp_Thread1 (version 2.0) [in thread_registration_apps() at main.c:1492]
DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:104]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1392]
DEBUG1: UST registration received with pid:11404 ppid:11401 uid:0 gid:0 sock:21 name:TestApp_Fork1 (version 2.0) [in thread_registration_apps() at main.c:1492]
DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:104]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1392]
DEBUG1: Futex n to 1 wait done [in futex_nto1_wait() at futex.c:90]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:75]
DEBUG1: Dispatching UST registration pid:11458 ppid:1 uid:0 gid:0 sock:17 name:TestApp_Thread1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1305]
DEBUG1: UST registration received with pid:11401 ppid:1 uid:0 gid:0 sock:22 name:TestApp_Fork1 (version 2.0) [in thread_registration_apps() at main.c:1492]
DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:104]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1392]
DEBUG1: Dispatching UST registration pid:11404 ppid:11401 uid:0 gid:0 sock:21 name:TestApp_Fork1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1305]
DEBUG1: Dispatching UST registration pid:11401 ppid:1 uid:0 gid:0 sock:22 name:TestApp_Fork1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1305]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1293]
DEBUG1: Futex n to 1 wait done [in futex_nto1_wait() at futex.c:90]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:75]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1293]
DEBUG3: Created hashtable size 4 at 0x6522f0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:11458 ppid:1 uid:0 gid:0 sock:17 name:TestApp_Thread1 (version 2.0) [in ust_app_register() at ust-app.c:1484]
DEBUG2: UST app PID 11458 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2837]
DEBUG1: Apps with sock 17 added to poll set [in thread_manage_apps() at main.c:1220]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1123]
DEBUG3: Created hashtable size 4 at 0x646440 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:11404 ppid:11401 uid:0 gid:0 sock:21 name:TestApp_Fork1 (version 2.0) [in ust_app_register() at ust-app.c:1484]
DEBUG1: UST registration received with pid:11347 ppid:1 uid:0 gid:0 sock:23 name:TestApp_type1 (version 2.0) [in thread_registration_apps() at main.c:1492]
DEBUG1: Futex n to 1 wake done [in futex_nto1_wake() at futex.c:104]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1392]
DEBUG1: Futex n to 1 wait done [in futex_nto1_wait() at futex.c:90]
DEBUG1: Futex n to 1 prepare done [in futex_nto1_prepare() at futex.c:75]
DEBUG1: Dispatching UST registration pid:11347 ppid:1 uid:0 gid:0 sock:23 name:TestApp_type1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1305]
DEBUG2: UST app PID 11404 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2837]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1293]
DEBUG1: Apps with sock 21 added to poll set [in thread_manage_apps() at main.c:1220]
DEBUG1: Apps thread polling on 4 fds [in thread_manage_apps() at main.c:1123]
DEBUG3: Created hashtable size 4 at 0x645f20 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:11401 ppid:1 uid:0 gid:0 sock:22 name:TestApp_Fork1 (version 2.0) [in ust_app_register() at ust-app.c:1484]
DEBUG2: UST app PID 11401 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2837]
DEBUG1: Apps with sock 22 added to poll set [in thread_manage_apps() at main.c:1220]
DEBUG1: Apps thread polling on 5 fds [in thread_manage_apps() at main.c:1123]
DEBUG3: Created hashtable size 4 at 0x6527e0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:11347 ppid:1 uid:0 gid:0 sock:23 name:TestApp_type1 (version 2.0) [in ust_app_register() at ust-app.c:1484]
DEBUG2: UST app PID 11347 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2837]
DEBUG1: Apps with sock 23 added to poll set [in thread_manage_apps() at main.c:1220]
DEBUG1: Apps thread polling on 6 fds [in thread_manage_apps() at main.c:1123]
Nov 22 22:12:10 SC-1 osafimmnd[6574]: Ccb 16246 COMMITTED (TraceC)
Nov 22 22:12:10 PL-4 osafimmnd[4925]: Ccb 16246 COMMITTED (TraceC)
Nov 22 22:12:10 SC-2 osafimmnd[5125]: Ccb 16246 COMMITTED (TraceC)
Nov 22 22:12:10 PL-3 osafimmnd[4916]: Ccb 16246 COMMITTED (TraceC)
Nov 22 22:12:10 SC-1 osafimmnd[6574]: Ccb 16247 COMMITTED (TraceC)
Nov 22 22:12:10 PL-4 osafimmnd[4925]: Ccb 16247 COMMITTED (TraceC)
Nov 22 22:12:10 SC-2 osafimmnd[5125]: Ccb 16247 COMMITTED (TraceC)
Nov 22 22:12:10 PL-3 osafimmnd[4916]: Ccb 16247 COMMITTED (TraceC)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2180]
DEBUG1: Waiting for 2 URIs from client ... [in process_client_msg() at main.c:2687]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session TestProf_1 created in (null) with ID 2 by UID 0 GID 0 [in session_create() at session.c:236]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x644950 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting network URI to consumer [in add_uri_to_consumer() at cmd.c:375]
DEBUG3: Consumer control URI set with port 52362 [in consumer_set_network_uri() at consumer.c:382]
DEBUG3: Consumer set network uri subdir path SC-1/./ [in consumer_set_network_uri() at consumer.c:434]
DEBUG3: Append domain trace name to subdir SC-1/./ [in add_uri_to_consumer() at cmd.c:402]
DEBUG2: Setting network URI to consumer [in add_uri_to_consumer() at cmd.c:375]
DEBUG3: Consumer data URI set with port 50027 [in consumer_set_network_uri() at consumer.c:391]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2067]
DEBUG3: Created hashtable size 4 at 0x64f9f0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64ff00 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x650440 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x650960 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: UST trace session create successful [in trace_ust_create_session() at trace-ust.c:238]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2019]
DEBUG3: Created hashtable size 4 at 0x650960 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Copy session consumer subdir SC-1/.//ust [in copy_session_consumer() at main.c:2037]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG1: Enabling channel channel0 for session TestProf_1 [in cmd_enable_channel() at cmd.c:822]
DEBUG2: Trace UST channel channel0 not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:141]
DEBUG3: Created hashtable size 4 at 0x646960 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x646e80 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST channel channel0 created [in trace_ust_create_channel() at trace-ust.c:302]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:273]
DEBUG2: UST app adding channel channel0 to global domain for session id 2 [in ust_app_create_channel_glb() at ust-app.c:2011]
DEBUG2: UST app pid: 11404 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x648400 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:959]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x6496e0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x649c20 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11404 and sock:21 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11404 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: UST app pid: 11401 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x64a280 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:959]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x65aa90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65ad30 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11401 and sock:22 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11401 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: UST app pid: 11347 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x65c240 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:959]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x65c9a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65ce80 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11347 and sock:23 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11347 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: UST app pid: 11458 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x65e560 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:959]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x65ed50 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65f290 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11458 and sock:17 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11458 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:298]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG3: No kernel session when tearing down session [in kernel_destroy_session() at kernel.c:701]
DEBUG2: Sending destroy relayd command to consumer... [in consumer_send_destroy_relayd() at consumer.c:47]
DEBUG2: Consumer send destroy relayd command done [in consumer_send_destroy_relayd() at consumer.c:67]
DEBUG1: Destroy all UST traces [in ust_app_destroy_trace_all() at ust-app.c:2531]
DEBUG1: Destroy tracing for ust app pid 11404 [in ust_app_destroy_trace() at ust-app.c:2429]
DEBUG1: Destroy tracing for ust app pid 11401 [in ust_app_destroy_trace() at ust-app.c:24DEBUDEBUG1: Destroy tracing for ust app pid 11347 [in ust_app_destroy_trace() at ust-app.c:2429]
DEBUG1: Destroy tracing for ust app pid 11458 [in ust_app_destroy_trace() at ust-app.c:2429]
DEBUG2: Trace UST destroy session 2 [in trace_ust_destroy_session() at trace-ust.c:667]
DEBUG1: Destroying session TestProf_1 [in session_destroy() at session.c:149]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG2: Trace destroy UST channel channel0 [in trace_ust_destroy_channel() at trace-ust.c:550]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 13 [in process_client_msg() at main.c:2180]
DEBUG1: Counting number of available session for UID 0 GID 0 [in lttng_sessions_count() at main.c:2151]
DEBUG1: Getting all available session for UID 0 GID 0 [in cmd_list_lttng_sessions() at cmd.c:2070]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
Nov 22 22:12:10 SC-1 osafimmnd[6574]: Ccb 16248 COMMITTED (TraceC)
Nov 22 22:12:10 PL-4 osafimmnd[4925]: Ccb 16248 COMMITTED (TraceC)
Nov 22 22:12:10 PL-3 osafimmnd[4916]: Ccb 16248 COMMITTED (TraceC)
Nov 22 22:12:10 SC-2 osafimmnd[5125]: Ccb 16248 COMMITTED (TraceC)
Nov 22 22:12:10 SC-1 osafimmnd[6574]: Ccb 16249 COMMITTED (TraceC)
Nov 22 22:12:10 PL-4 osafimmnd[4925]: Ccb 16249 COMMITTED (TraceC)
Nov 22 22:12:10 PL-3 osafimmnd[4916]: Ccb 16249 COMMITTED (TraceC)
Nov 22 22:12:10 SC-2 osafimmnd[5125]: Ccb 16249 COMMITTED (TraceC)
64235 22:12:10 11/22/2012 IN TraceC "DBG: Performing activate after relayD wait for session TestProf_1
64236 22:12:10 11/22/2012 IN TraceC "DBG: relayD ip address is found: 192.168.0.1
64237 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-3,traceMId=1, op: 2, addr: 0x693C10
64238 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-4,traceMId=1, op: 2, addr: 0x6A4580
64239 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-1,traceMId=1, op: 2, addr: 0x69DE20
64240 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-2,traceMId=1, op: 2, addr: 0x6A41E0
64241 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x693C10
64242 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x6A4580
64243 22:12:10 11/22/2012 IN TraceP_PL-3 "Activating
64244 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x69DE20
64245 22:12:10 11/22/2012 IN TraceP_PL-4 "Activating
64246 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x6A41E0
64247 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: LTTNG session activation requested, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64248 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Invoking lttng_create_session, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64249 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Invoking lttng_channel_set_default_attr, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64250 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Invoking lttng_enable_channel, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64251 22:12:10 11/22/2012 IN TraceP_SC-1 "Activating
64252 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: LTTNG session activation requested, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64253 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Invoking lttng_create_session, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64254 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Invoking lttng_channel_set_default_attr, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64255 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Invoking lttng_enable_channel, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64256 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: LTTNG session activation requested, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64257 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Invoking lttng_create_session, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64258 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: LTTNG, enabling event, event name com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA
64259 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Invoking lttng_enable_event_with_filter, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64260 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Invoking lttng_channel_set_default_attr, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64261 22:12:10 11/22/2012 IN TraceP_SC-2 "Activating
64262 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Invoking lttng_enable_channel, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64263 22:12:10 11/22/2012 ER TraceP_PL-3 "Error: sessionD enable event with filter failure for event com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA ! error: Not enough memory for filter bytecode
64264 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Return for invocation -41 value: 20, return code: 1 , SA_AIS_OK
64265 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: LTTNG, enabling event, event name com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA
64266 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Invoking lttng_enable_event_with_filter, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64267 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: LTTNG session activation requested, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64268 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Invoking lttng_create_session, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64269 22:12:10 11/22/2012 ER TraceP_PL-4 "Error: sessionD enable event with filter failure for event com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA ! error: Not enough memory for filter bytecode
64270 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Return for invocation -42 value: 20, return code: 1 , SA_AIS_OK
64271 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Invoking lttng_channel_set_default_attr, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64272 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Invoking lttng_enable_channel, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64273 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: LTTNG, enabling event, event name com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA
64274 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Invoking lttng_enable_event_with_filter, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64275 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: LTTNG, enabling event, event name com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA
64276 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Invoking lttng_enable_event_with_filter, session name TestProf_1 with url net://192.168.0.1:52362:50027/./
64277 22:12:10 11/22/2012 ER TraceP_SC-2 "Error: sessionD enable event with filter failure for event com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA ! error: Not enough memory for filter bytecode
64278 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Return for invocation -44 value: 20, return code: 1 , SA_AIS_OK
64279 22:12:10 11/22/2012 ER TraceP_SC-1 "Error: sessionD enable event with filter failure for event com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA ! error: Not enough memory for filter bytecode
64280 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Return for invocation -43 value: 20, return code: 1 , SA_AIS_OK
64281 22:12:10 11/22/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
64282 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
64283 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
64284 22:12:10 11/22/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
64285 22:12:10 11/22/2012 ER TraceC "Error: TraceP "tracePId=PL-3,traceMId=1" could not activate Session "traceSessionRecordingId=TestProf_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
64286 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
64287 22:12:10 11/22/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
64288 22:12:10 11/22/2012 ER TraceC "Error: TraceP "tracePId=PL-4,traceMId=1" could not activate Session "traceSessionRecordingId=TestProf_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
64289 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
64290 22:12:10 11/22/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
64291 22:12:10 11/22/2012 ER TraceC "Error: TraceP "tracePId=SC-2,traceMId=1" could not activate Session "traceSessionRecordingId=TestProf_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
64292 22:12:10 11/22/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
64293 22:12:10 11/22/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
64294 22:12:10 11/22/2012 ER TraceC "Error: TraceP "tracePId=SC-1,traceMId=1" could not activate Session "traceSessionRecordingId=TestProf_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
64295 22:12:10 11/22/2012 ER TraceC "No successful replies for session "traceSessionRecordingId=TestProf_1,traceMId=1". Canceling.
64296 22:12:10 11/22/2012 IN TraceC "DBG: Requesting relay-d cancelation for session traceSessionRecordingId=TestProf_1,traceMId=1
64297 22:12:10 11/22/2012 IN TraceC "DBG: Canceling relayD for session TestProf_1
64298 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-3,traceMId=1, op: 4, addr: 0x6A4770
64299 22:12:10 11/22/2012 IN TraceC "DBG: Adding Cancel op 0x6A4770 for tracePId=PL-3,traceMId=1
64300 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-4,traceMId=1, op: 4, addr: 0x6A46E0
64301 22:12:10 11/22/2012 IN TraceC "DBG: Adding Cancel op 0x6A46E0 for tracePId=PL-4,traceMId=1
64302 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-1,traceMId=1, op: 4, addr: 0x6A4860
64303 22:12:10 11/22/2012 IN TraceC "DBG: Adding Cancel op 0x6A4860 for tracePId=SC-1,traceMId=1
64304 22:12:10 11/22/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-2,traceMId=1, op: 4, addr: 0x6A4380
64305 22:12:10 11/22/2012 IN TraceC "DBG: Adding Cancel op 0x6A4380 for tracePId=SC-2,traceMId=1
64306 22:12:10 11/22/2012 IN TraceC "DBG: Try to async-remove directory "/home/trace//TestProf_1"
64307 22:12:10 11/22/2012 IN TraceC "DBG: remove called to delete file /home/trace//.tmp/TestProf_1
64308 22:12:10 11/22/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
64309 22:12:10 11/22/2012 IN TraceC "DBG: Received death of pid 14531 with ret 9.
64310 22:12:10 11/22/2012 IN TraceC "DBG: No handler for pid 14531.
64311 22:12:10 11/22/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestProf_1 has been deleted, moved, replaced or a delayed creation notification has been received in /home/trace
64312 22:12:10 11/22/2012 IN TraceC "DBG: TraceCHouseKeeping:directoryDeleteHandler is deleting TestProf_1
64313 22:12:10 11/22/2012 IN TraceC "DBG: TraceCHouseKeeping: directoryDeleteHandler is deleting TestProf_1
64314 22:12:10 11/22/2012 IN TraceC "DBG: directoryDeleteHandler : directory TestProf_1 is being deleted
64315 22:12:10 11/22/2012 IN TraceC "DBG: Try to remove directory "/home/trace//.tmp/TestProf_1"
64316 22:12:10 11/22/2012 IN TraceC "DBG: Remove Directory "/home/trace//.tmp/TestProf_1" Deleted!
64317 22:12:10 11/22/2012 IN TraceC "DBG: Completed deletion of "/home/trace//.tmp/TestProf_1"
64318 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x6A4770
64319 22:12:10 11/22/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
64320 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x6A46E0
64321 22:12:10 11/22/2012 IN TraceP_PL-3 "Cancelling
64322 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: TraceP Cancel: MO object traceSessionRecordingId=TestProf_1,traceMId=1 not found in registry !
64323 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Session count 0
64324 22:12:10 11/22/2012 IN TraceP_PL-3 "DBG: Return for invocation -45 value: 1, return code: 1 , SA_AIS_OK
64325 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x6A4860
64326 22:12:10 11/22/2012 IN TraceP_PL-4 "Cancelling
64327 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: TraceP Cancel: MO object traceSessionRecordingId=TestProf_1,traceMId=1 not found in registry !
64328 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Session count 0
64329 22:12:10 11/22/2012 IN TraceC "DBG: Invoking admin op 0x6A4380
64330 22:12:10 11/22/2012 IN TraceP_PL-4 "DBG: Return for invocation -46 value: 1, return code: 1 , SA_AIS_OK
64331 22:12:10 11/22/2012 IN TraceP_SC-1 "Cancelling
64332 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: TraceP Cancel: MO object traceSessionRecordingId=TestProf_1,traceMId=1 not found in registry !
64333 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Session count 0
64334 22:12:10 11/22/2012 IN TraceP_SC-1 "DBG: Return for invocation -47 value: 1, return code: 1 , SA_AIS_OK
64335 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
64336 22:12:10 11/22/2012 IN TraceP_SC-2 "Cancelling
64337 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: TraceP Cancel: MO object traceSessionRecordingId=TestProf_1,traceMId=1 not found in registry !
64338 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
64339 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Session count 0
64340 22:12:10 11/22/2012 IN TraceP_SC-2 "DBG: Return for invocation -48 value: 1, return code: 1 , SA_AIS_OK
64341 22:12:10 11/22/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
64342 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
64343 22:12:10 11/22/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
64344 22:12:10 11/22/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
64345 22:12:10 11/22/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
64346 22:12:10 11/22/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
64347 22:12:10 11/22/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
64348 22:12:10 11/22/2012 IN TraceC "DBG: cancelSessionOnTracePsComplete deleting ConvertAsyncActionProgress if it exists traceSessionRecordingId=TestProf_1,traceMId=1
64349 22:12:10 11/22/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
64350 22:12:10 11/22/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
IMM ERROR: SA_AIS_ERR_FAILED_OPERATION
Thu Nov 22 22:12:11 EST 2012
root 14495 2028 0 22:12 pts/3 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 14514 14495 0 22:12 pts/3 00:00:00 lttng-consumerd --verbose -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 23324 1 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 23332 23324 0 21:17 ? 00:00:00 /opt/trace_ea/bin/TraceEa
root 25334 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_c
root 25346 1 0 21:20 ? 00:00:00 /opt/trace/sbin/trace_p
Thu Nov 22 22:12:11 EST 2012
Printing Profile
####################
Thu Nov 22 22:12:11 EST 2012
consistentLogs : NOT_ENFORCED
description : ""
latestSessionId : 1
logLevelDefault : TRACE_DEBUG_SYSTEM(7)
state : INACTIVE
traceExpressions : com_ericsson_cba_trace_testapp_lowtraf:OnePerSecA,TRACE_DEBUG_PROGRAM(8)
--------------------------------
progress.actionName : cancelSession
progress.additionalInfo : Session Cancelled: No successful replies for session activation
progress.info : Trace cancellation is complete
progress.percentage : 100
progress.result : SUCCESS
progress.resultInfo : Trace cancelSession was completed successfully
progress.state : FINISHED
progress.timeActionCompleted : 11/22/12T22:12:10-0500
progress.timeActionStarted : 11/22/12T22:12:10-0500
progress.timeOfLastStatusUpdate : 11/22/12T22:12:10-0500
Thu Nov 22 22:12:11 EST 2012
Deleting Profile
####################
Thu Nov 22 22:12:11 EST 2012
Nov 22 22:12:11 SC-1 osafimmnd[6574]: Ccb 16251 COMMITTED (TraceCLI)
Nov 22 22:12:11 SC-2 osafimmnd[5125]: Ccb 16251 COMMITTED (TraceCLI)
Nov 22 22:12:11 PL-4 osafimmnd[4925]: Ccb 16251 COMMITTED (TraceCLI)
Nov 22 22:12:11 PL-3 osafimmnd[4916]: Ccb 16251 COMMITTED (TraceCLI)
###########################################################################
###########################################################################
###########################################################################
SC-1:/storage/no-backup/coremw/var/log/saflog # DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3250]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2180]
DEBUG1: Waiting for 1 URIs from client ... [in process_client_msg() at main.c:2687]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session _Trace_EA created in (null) with ID 3 by UID 0 GID 0 [in session_create() at session.c:236]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x644950 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting trace directory path from URI to /cluster/temp/eusgarc/deleteme/ [in add_uri_to_consumer() at cmd.c:407]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2067]
DEBUG3: Created hashtable size 4 at 0x650490 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x6509a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x650ee0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x651400 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: UST trace session create successful [in trace_ust_create_session() at trace-ust.c:238]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2019]
DEBUG3: Created hashtable size 4 at 0x651400 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Copy session consumer subdir /ust [in copy_session_consumer() at main.c:2037]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG1: Enabling channel channel0 for session _Trace_EA [in cmd_enable_channel() at cmd.c:822]
DEBUG2: Trace UST channel channel0 not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:141]
DEBUG3: Created hashtable size 4 at 0x651970 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x651e90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST channel channel0 created [in trace_ust_create_channel() at trace-ust.c:302]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:273]
DEBUG2: UST app adding channel channel0 to global domain for session id 3 [in ust_app_create_channel_glb() at ust-app.c:2011]
DEBUG2: UST app pid: 11404 session id 3 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x647bf0 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:959]
DEBUG2: UST app session created successfully with handle 9 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x6483e0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64a470 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11404 and sock:21 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11404 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: UST app pid: 11401 session id 3 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x64aad0 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:959]
DEBUG2: UST app session created successfully with handle 9 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x65a7e0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65ac90 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11401 and sock:22 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11401 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: UST app pid: 11347 session id 3 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x65c1a0 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:959]
DEBUG2: UST app session created successfully with handle 9 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x65c930 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65ce70 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11347 and sock:23 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11347 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: UST app pid: 11458 session id 3 not found, creating it [in create_ust_app_session() at ust-app.c:1050]
DEBUG3: Created hashtable size 4 at 0x65e550 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:959]
DEBUG2: UST app session created successfully with handle 9 [in create_ust_app_session() at ust-app.c:1077]
DEBUG3: Created hashtable size 4 at 0x65ed40 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65f280 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app channel channel0 allocated [in alloc_ust_app_channel() at ust-app.c:374]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:901]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:936]
DEBUG2: UST app channel channel0 created successfully for pid:11458 and sock:17 [in create_ust_channel() at ust-app.c:787]
DEBUG2: UST app create channel channel0 for PID 11458 completed [in create_ust_app_channel() at ust-app.c:1252]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:298]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG2: Trace UST channel channel0 found by name [in trace_ust_find_channel_by_name() at trace-ust.c:136]
DEBUG2: Trace UST event _TRACE_EA_FAKE_EVENT NOT found [in trace_ust_find_event() at trace-ust.c:174]
DEBUG2: Trace UST event _TRACE_EA_FAKE_EVENT, loglevel (0,-1) created [in trace_ust_create_event() at trace-ust.c:378]
DEBUG1: UST app creating event _TRACE_EA_FAKE_EVENT for all apps for session id 3 [in ust_app_create_event_glb() at ust-app.c:2136]
DEBUG3: UST app event _TRACE_EA_FAKE_EVENT allocated [in alloc_ust_app_event() at ust-app.c:408]
DEBUG2: UST app event _TRACE_EA_FAKE_EVENT created successfully for pid:11404 [in create_ust_event() at ust-app.c:827]
DEBUG2: UST app create event _TRACE_EA_FAKE_EVENT for PID 11404 completed [in create_ust_app_event() at ust-app.c:1301]
DEBUG3: UST app event _TRACE_EA_FAKE_EVENT allocated [in alloc_ust_app_event() at ust-app.c:408]
DEBUG2: UST app event _TRACE_EA_FAKE_EVENT created successfully for pid:11401 [in create_ust_event() at ust-app.c:827]
DEBUG2: UST app create event _TRACE_EA_FAKE_EVENT for PID 11401 completed [in create_ust_app_event() at ust-app.c:1301]
DEBUG3: UST app event _TRACE_EA_FAKE_EVENT allocated [in alloc_ust_app_event() at ust-app.c:408]
DEBUG2: UST app event _TRACE_EA_FAKE_EVENT created successfully for pid:11347 [in create_ust_event() at ust-app.c:827]
DEBUG2: UST app create event _TRACE_EA_FAKE_EVENT for PID 11347 completed [in create_ust_app_event() at ust-app.c:1301]
DEBUG3: UST app event _TRACE_EA_FAKE_EVENT allocated [in alloc_ust_app_event() at ust-app.c:408]
DEBUG2: UST app event _TRACE_EA_FAKE_EVENT created successfully for pid:11458 [in create_ust_event() at ust-app.c:827]
DEBUG2: UST app create event _TRACE_EA_FAKE_EVENT for PID 11458 completed [in create_ust_app_event() at ust-app.c:1301]
DEBUG1: Event UST _TRACE_EA_FAKE_EVENT created in channel channel0 [in event_ust_enable_tracepoint() at event.c:476]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3297]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3159]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3201]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3246]
DEBUG1: Processing client command 16 [in process_client_msg() at main.c:2180]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2251]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG2: Setting relayd for session _Trace_EA [in setup_relayd() at cmd.c:643]
DEBUG1: Starting all UST traces [in ust_app_start_trace_all() at ust-app.c:2479]
DEBUG1: Starting tracing for ust app pid 11404 [in ust_app_start_trace() at ust-app.c:2190]
DEBUG3: mkdir() recursive /cluster/temp/eusgarc/deleteme/ with mode 504 for uid 0 and gid 0 [in run_as_mkdir_recursive() at runas.c:342]
DEBUG1: Using run_as_clone [in run_as() at runas.c:325]
DEBUG2: UST metadata opened for app pid 11404 [in create_ust_app_metadata() at ust-app.c:1342]
DEBUG2: UST metadata stream object created for app pid 11404 [in create_ust_app_metadata() at ust-app.c:1360]
DEBUG2: UST stream 1 ready (handle: 5) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG2: UST stream 2 ready (handle: 6) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG2: UST stream 3 ready (handle: 7) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG2: UST stream 4 ready (handle: 8) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG1: Sending metadata stream fd to consumer on 20 [in ust_consumer_send_session() at ust-consumer.c:303]
DEBUG1: UST consumer sending metadata stream fd [in send_metadata() at ust-consumer.c:206]
DEBUG3: mkdir() recursive /cluster/temp/eusgarc/deleteme///ust/TestApp_Fork1-11404-20121122-221212/ with mode 504 for uid 0 and gid 0 [in run_as_mkdir_recursive() at runas.c:342]
DEBUG1: Using run_as_clone [in run_as() at runas.c:325]
DEBUG1: Sending streams of channel channel0 to UST consumer [in send_channel_streams() atDEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:134]
DEBUG1: consumer_add_channel 33 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:148]
DEBUG1: Allocated channel (key 33, shm_fd -1, wait_fd -1, mmap_len 768, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:851]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2523]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2505]
DEBUG1: UDEBUG2: Sending stream 41 of channel channel0 to kernel consumer [in send_channel_stream() at ust-consumer.c:90]
DEBUG2: Sending stream 43 of channel channel0 to kernel consumer [in send_channel_stream() at ust-consumer.c:90]
DEBUG1: UST consumer channel streams sent [in send_channel_streams() at ust-consumer.c:172]
DEBUG1: consumer fds (metadata and channel streams) sent [in ust_consumer_send_session() at ust-consumer.c:333]
DEBUG1: Starting tracing for ust app pid 11401 [in ust_app_start_trace() at ust-app.c:2190]
DEBUG3: mkdir() recursive /cluster/temp/eusgarc/deleteme/ with mode 504 for uid 0 and gid 0 [in run_as_mkdir_recursive() at runas.c:342]
DEBUG1: Using run_as_clone [in run_as() at runas.c:325]
DEBUG2: UST metadata opened for app pid 11401 [in create_ust_app_metadata() at ust-app.c:1342]
DEBUG2: UST metadata stream object created for app pid 11401 [in create_ust_app_metadata() at ust-app.c:1360]
DEBUG2: UST stream 1 ready (handle: 5) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG2: UST stream 2 ready (handle: 6) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG2: UST stream 3 ready (handle: 7) [in ust_app_start_trace() at ust-app.c:2280]
a_poll() at consumer.c:2028]
andle: 8) [in ust_app_start_trace() at ust-app.c:2280]
DEBUG1: Sending metadata stream fd to consumer on 20 [in ust_consumer_send_session() at ust-consumer.c:303]
DEBUG1: UST consumer sending metadata stream fd [in send_metadata() at ust-consumer.c:206]
DEBUG3: mkdir() recursive /cluster/temp/eusgarc/deleteme///ust/TestApp_Fork1-11401-20121122-221212/ with mode 504 for uid 0 and gid 0 [in run_as_mkdir_recursive() at runas.c:342]
DEBUG1: Using run_as_clone [in run_as() at runas.c:325]
(1-1/3)