Project

General

Profile

Bug #415 » bug415_verbose_no_tc_40sec_delay.txt

Jesus Garcia, 12/19/2012 12:27 PM

 
SC-1:/storage/no-backup/coremw/var/log/saflog # date;ps -eaf | egrep "trace|lttng" | grep -v grep
Wed Dec 19 12:14:18 EST 2012
root 7055 1 0 12:08 ? 00:00:00 lttng-sessiond -d
root 7972 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_c
root 7973 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_p
root 21870 1 0 Dec18 ? 00:00:11 /opt/trace_ea/bin/TraceEa
root 21878 21870 0 Dec18 ? 00:00:02 /opt/trace_ea/bin/TraceEa
SC-1:/storage/no-backup/coremw/var/log/saflog # pkill -9 lttng-sessiond; usleep 90000; lttng-sessiond -vvv --verbose-consumer --no-kernel > /cluster/temp/eusgarc/sc1_sessiond.log 2>&1 &
[7] 9046
SC-1:/storage/no-backup/coremw/var/log/saflog # sleep 2;/cluster/temp/eusgarc/test_once
DEBUG3: Creating LTTng run directory: /var/run/lttng [in create_lttng_rundir() at main.c:3692]
DEBUG2: Kernel consumer err path: /var/run/lttng/kconsumerd/error [in main() at main.c:3940]
DEBUG2: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command [in main() at main.c:3942]
DEBUG1: Client socket path /var/run/lttng/client-lttng-sessiond [in main() at main.c:3995]
DEBUG1: Application socket path /var/run/lttng/apps-lttng-sessiond [in main() at main.c:3996]
DEBUG1: LTTng run directory path: /var/run/lttng [in main() at main.c:3997]
DEBUG2: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error [in main() at main.c:4006]
DEBUG2: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command [in main() at main.c:4008]
DEBUG2: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error [in main() at main.c:4017]
DEBUG2: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command [in main() at main.c:4019]
DEBUG3: Created hashtable size 4 at 0x64a0a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64a5c0 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:3734]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd64 [in set_consumer_sockets() at main.c:3734]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd32 [in set_consumer_sockets() at main.c:3734]
DEBUG1: Signal handler set for SIGTERM, SIGPIPE and SIGINT [in set_signal_handler() at main.c:3826]
DEBUG3: Session daemon client socket 8 and application socket 9 created [in init_daemon_socket() at main.c:3596]
Warning: No tracing group detected
DEBUG1: epoll set max size is 403353 [in compat_epoll_set_max_size() at compat-epoll.c:270]
DEBUG1: Command subsystem initialized [in cmd_init() at cmd.c:2423]
DEBUG1: [thread] Manage health check started [in thread_manage_health() at main.c:2953]
DEBUG1: [thread] Manage client started [in thread_manage_clients() at main.c:3147]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: [thread] Dispatch UST command started [in thread_dispatch_ust_registration() at main.c:1300]
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:1310]
DEBUG1: [thread] Manage application registration started [in thread_registration_apps() at main.c:1378]
DEBUG1: Notifying applications of session daemon state: 1 [in notify_ust_apps() at main.c:496]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: [thread] Manage application started [in thread_manage_apps() at main.c:1107]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1135]
DEBUG1: Got the wait shm fd 16 [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:1413]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health state current 10, last 0, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 5, last 0, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 0, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 0, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 0, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 0, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
Wed Dec 19 12:14:20 EST 2012
root 7972 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_c
root 7973 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_p
root 9046 26613 0 12:14 pts/0 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 21870 1 0 Dec18 ? 00:00:11 /opt/trace_ea/bin/TraceEa
root 21878 21870 0 Dec18 ? 00:00:02 /opt/trace_ea/bin/TraceEa
Wed Dec 19 12:14:20 EST 2012
Creating Profile
####################
Wed Dec 19 12:14:20 EST 2012
Dec 19 12:14:20 SC-1 osafimmnd[6451]: Ccb 563 COMMITTED (TraceCLI)
Dec 19 12:14:20 PL-3 osafimmnd[4905]: Ccb 563 COMMITTED (TraceCLI)
Dec 19 12:14:20 PL-4 osafimmnd[4935]: Ccb 563 COMMITTED (TraceCLI)
Dec 19 12:14:20 SC-2 osafimmnd[5121]: Ccb 563 COMMITTED (TraceCLI)
Wed Dec 19 12:14:20 EST 2012
Wait 1 sec...
7076 12:14:20 12/19/2012 IN TraceC "DBG: ProfileAdmin::profileIdValidator was called
7077 12:14:20 12/19/2012 IN TraceC "DBG: newvalue size=23
7078 12:14:20 12/19/2012 IN TraceC "DBG: newvalue=traceProfileId=TestProf

7079 12:14:20 12/19/2012 IN TraceC "DBG: traceExpressionsValidator was called for traceExpression with size = 1.
7080 12:14:20 12/19/2012 IN TraceC "DBG: conditionValidator: About to create a temporary session _TraceCValidator_yttvBK in path /tmp/_TraceCValidator_yttvBK - Invoke lttng_create_session
7081 12:14:20 12/19/2012 IN TraceC "DBG: conditionValidator: Invoke lttng_create_handle for temporary session _TraceCValidator_yttvBK.
7082 12:14:20 12/19/2012 IN TraceC "DBG: conditionValidator: Invoke lttng_set_default_handle_attr for temporary session _TraceCValidator_yttvBK
7083 12:14:20 12/19/2012 IN TraceC "DBG: conditionValidator: Invoke lttng_destroy_session for temporary session _TraceCValidator_yttvBK
7084 12:14:20 12/19/2012 IN TraceC "DBG: Try to remove directory "/tmp/_TraceCValidator_yttvBK"
7085 12:14:20 12/19/2012 IN TraceC "DBG: Remove Directory "/tmp/_TraceCValidator_yttvBK" Deleted!
7086 12:14:20 12/19/2012 IN TraceC "DBG: conditionValidator: Reply recieved from lttng_destroy_session for temporary session _TraceCValidator_yttvBK.
Dec 19 12:14:20 SC-1 osafimmnd[6451]: Ccb 564 COMMITTED (TraceC)
Dec 19 12:14:20 PL-3 osafimmnd[4905]: Ccb 564 COMMITTED (TraceC)
Dec 19 12:14:20 SC-2 osafimmnd[5121]: Ccb 564 COMMITTED (TraceC)
Dec 19 12:14:20 PL-4 osafimmnd[4935]: Ccb 564 COMMITTED (TraceC)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2204]
DEBUG1: Waiting for 1 URIs from client ... [in process_client_msg() at main.c:2711]
DEBUG2: Trying to find session by name _TraceCValidator_yttvBK [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session _TraceCValidator_yttvBK 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_yttvBK [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x655af0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting trace directory path from URI to /tmp/_TraceCValidator_yttvBK [in add_uri_to_consumer() at cmd.c:407]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session _TraceCValidator_yttvBK by name [in process_client_msg() at main.c:2275]
DEBUG2: Trying to find session by name _TraceCValidator_yttvBK [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2091]
DEBUG3: Created hashtable size 4 at 0x64e940 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64ee80 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64f3c0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65b090 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:239]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2043]
DEBUG3: Created hashtable size 4 at 0x65b090 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Copy session consumer subdir /ust [in copy_session_consumer() at main.c:2061]
DEBUG1: Spawning consumerd [in spawn_consumerd() at main.c:1722]
DEBUG2: Consumer pid 9063 [in start_consumerd() at main.c:1903]
DEBUG2: Spawning consumer control thread [in start_consumerd() at main.c:1906]
DEBUG1: [thread] Manage consumer started [in thread_manage_consumer() at main.c:856]
DEBUG1: Using 64-bit UST consumer at: /usr/lib64/lttng/libexec/lttng-consumerd [in spawn_consumerd() at main.c:1796]
DEBUG1: epoll set max size is 403353 [in compat_epoll_set_max_size() at compat-epoll.c:270]
DEBUG3: Created hashtable size 4 at 0x627030 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x627570 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x627ab0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x627ff0 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 0x628850 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: Thread metadata poll started [in consumer_thread_metadata_poll() at consumer.c:2092]
DEBUG1: Metadata main loop started [in consumer_thread_metadata_poll() at consumer.c:2107]
DEBUG1: Metadata poll wait with 1 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG3: Created hashtable size 4 at 0x7f23d40008b0 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:2545]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: polling on 1 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Sending ready command to lttng-sessiond [in consumer_thread_sessiond_poll() at consumer.c:2558]
DEBUG1: Connection on client_socket [in consumer_thread_sessiond_poll() at consumer.c:2581]
nsumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:179]
DEBUG1: Enabling channel channel0 for session _TraceCValidator_yttvBK [in cmd_enable_channel() at cmd.c:823]
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 0x65ca20 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65cf60 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:303]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:277]
DEBUG2: UST app adding channel channel0 to global domain for session id 0 [in ust_app_create_channel_glb() at ust-app.c:2043]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:302]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session _TraceCValidator_yttvBK by name [in process_client_msg() at main.c:2275]
DEBUG2: Trying to find session by name _TraceCValidator_yttvBK [in session_find_by_name() at session.c:122]
DEBUG3: No kernel session when tearing down session [in kernel_destroy_session() at kernel.c:700]
DEBUG1: Destroy all UST traces [in ust_app_destroy_trace_all() at ust-app.c:2570]
DEBUG2: Trace UST destroy session 0 [in trace_ust_destroy_session() at trace-ust.c:668]
DEBUG1: Destroying session _TraceCValidator_yttvBK [in session_destroy() at session.c:149]
DEBUG2: Trace destroy UST channel channel0 [in trace_ust_destroy_channel() at trace-ust.c:551]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
Wed Dec 19 12:14:21 EST 2012
root 7972 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_c
root 7973 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_p
root 9046 26613 0 12:14 pts/0 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 9063 9046 0 12:14 pts/0 00:00:00 lttng-consumerd --verbose -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 21870 1 0 Dec18 ? 00:00:11 /opt/trace_ea/bin/TraceEa
root 21878 21870 0 Dec18 ? 00:00:02 /opt/trace_ea/bin/TraceEa
Wed Dec 19 12:14:21 EST 2012
Activating Profile
####################
Wed Dec 19 12:14:21 EST 2012
7087 12:14:20 12/19/2012 IN TraceC "DBG: Create: class: AsyncActionProgress, parentName: traceProfileId=TestProf,traceMId=1
7088 12:14:21 12/19/2012 IN TraceC "DBG: Activating
Dec 19 12:14:21 SC-1 osafimmnd[6451]: Ccb 566 COMMITTED (TraceC)
Dec 19 12:14:21 PL-3 osafimmnd[4905]: Ccb 566 COMMITTED (TraceC)
Dec 19 12:14:21 SC-2 osafimmnd[5121]: Ccb 566 COMMITTED (TraceC)
Dec 19 12:14:21 PL-4 osafimmnd[4935]: Ccb 566 COMMITTED (TraceC)
Dec 19 12:14:21 SC-1 osafimmnd[6451]: Ccb 567 COMMITTED (TraceC)
Dec 19 12:14:21 PL-3 osafimmnd[4905]: Ccb 567 COMMITTED (TraceC)
Dec 19 12:14:21 PL-4 osafimmnd[4935]: Ccb 567 COMMITTED (TraceC)
Dec 19 12:14:21 SC-2 osafimmnd[5121]: Ccb 567 COMMITTED (TraceC)
Dec 19 12:14:21 SC-1 osafimmnd[6451]: Ccb 568 COMMITTED (TraceC)
Dec 19 12:14:21 PL-3 osafimmnd[4905]: Ccb 568 COMMITTED (TraceC)
Dec 19 12:14:21 SC-2 osafimmnd[5121]: Ccb 568 COMMITTED (TraceC)
Dec 19 12:14:21 PL-4 osafimmnd[4935]: Ccb 568 COMMITTED (TraceC)
Dec 19 12:14:22 SC-1 osafimmnd[6451]: Ccb 569 COMMITTED (TraceC)
Dec 19 12:14:22 PL-4 osafimmnd[4935]: Ccb 569 COMMITTED (TraceC)
Dec 19 12:14:22 PL-3 osafimmnd[4905]: Ccb 569 COMMITTED (TraceC)
Dec 19 12:14:22 SC-2 osafimmnd[5121]: Ccb 569 COMMITTED (TraceC)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2204]
DEBUG1: Waiting for 2 URIs from client ... [in process_client_msg() at main.c:2711]
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 1 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 0x65c8e0 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 59383 [in consumer_set_network_uri() at consumer.c:420]
DEBUG3: Consumer set network uri subdir path SC-1/./ [in consumer_set_network_uri() at consumer.c:472]
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 50886 [in consumer_set_network_uri() at consumer.c:429]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2275]
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:2091]
DEBUG3: Created hashtable size 4 at 0x65ce20 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x659bf0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65a130 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65a650 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:239]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2043]
DEBUG3: Created hashtable size 4 at 0x65a650 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:2061]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:179]
DEBUG1: Enabling channel channel0 for session TestProf_1 [in cmd_enable_channel() at cmd.c:823]
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 0x65abc0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65b100 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:303]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:277]
DEBUG2: UST app adding channel channel0 to global domain for session id 1 [in ust_app_create_channel_glb() at ust-app.c:2043]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:302]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2275]
DEBUG2: Trying to find session by name TestProf_1 [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:179]
DEBUG2: Trace UST channel channel0 found by name [in trace_ust_find_channel_by_name() at trace-ust.c:136]
DEBUG2: Trace UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA NOT found [in trace_ust_find_event() at trace-ust.c:174]
DEBUG2: Trace UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA, loglevel (1,10) created [in trace_ust_create_event() at trace-ust.c:379]
DEBUG1: UST app creating event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA for all apps for session id 1 [in ust_app_create_event_glb() at ust-app.c:2171]
DEBUG1: Event UST com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA 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:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 16 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2275]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG2: Setting relayd for session TestProf_1 [in setup_relayd() at cmd.c:644]
DEBUG3: Relayd connect ... [in relayd_connect() at relayd.c:315]
DEBUG3: Creating relayd stream socket from URI [in create_connect_relayd() at cmd.c:492]
DEBUG1: Relayd version check for major.minor 2.1 [in relayd_version_check() at relayd.c:219]
DEBUG3: Relayd sending command 5 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 8 [in recv_reply() at relayd.c:90]
DEBUG2: Relayd version is compatible [in relayd_version_check() at relayd.c:254]
DEBUG3: Sending relayd sock info to consumer on 20 [in consumer_send_relayd_socket() at consumer.c:690]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: Consumer adding relayd socket (idx: 2) [in consumer_add_relayd_socket() at consumer.c:2731]
DEBUG3: Sending relayd socket file descriptor to consumer [in consumer_send_relayd_socket() at consumer.c:702]
DEBUG2: Consumer relayd socket sent [in consumer_send_relayd_socket() at consumer.c:708]
DEBUG3: Relayd closing socket 21 [in relayd_close() at relayd.c:328]
DEBUG3: Relayd connect ... [in relayd_connect() at relayd.c:315]
DEBUG3: Creating relayd data socket from URI [in create_connect_relayd() at cmd.c:502]
DEBUG3: Sending relayd sock info to consumer on 20 [in consumer_send_relayd_socket() at consumer.c:690]
DEBUG1: Relayd session created with id 4 [in relayd_create_session() at relayd.c:144]
DEBUG1: Consumer control socket created successfully with net idx 2 (fd: 18) [in consumer_add_relayd_socket() at consumer.c:2848]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: Consumer adding relayd socket (idx: 2) [in consumer_add_relayd_socket() at consumer.c:2731]
DEBUG3: Sending relayd socket file descriptor to consumer [in consumer_send_relayd_socket() at consumer.c:702]
DEBUG2: Consumer relayd socket sent [in consumer_send_relayd_socket() at consumer.c:708]
DEBUG3: Relayd closing socket 21 [in relayd_close() at relayd.c:328]
DEBUG1: Starting all UST traces [in ust_app_start_trace_all() at ust-app.c:2518]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
7089 12:14:21 12/19/2012 IN TraceC "DBG: creating session traceSessionRecordingId=TestProf_1,traceMId=1 as a runtime object
7090 12:14:21 12/19/2012 NO TraceC "Activating Session TestProf_1.
7091 12:14:21 12/19/2012 IN TraceC "DBG: Directory /storage/no-backup/tracecc-apr9010500//TestProf_1 was created successfully!
7092 12:14:21 12/19/2012 IN TraceC "DBG: Return for invocation 1 value: 1, return code: 1 , SA_AIS_OK
7093 12:14:21 12/19/2012 IN TraceC "DBG: performActivate: Starting RelayD for session TestProf_1.
7094 12:14:21 12/19/2012 IN TraceC "DBG: relayD ip address is found, IP address: 192.168.0.1 for host: SC-1
7095 12:14:21 12/19/2012 IN TraceC "DBG: RelayDManager::start() Control port selected: 59383
7096 12:14:21 12/19/2012 IN TraceC "DBG: RelayDManager::start() Data port selected: 50886
7097 12:14:21 12/19/2012 IN TraceC "DBG: RelayDManager::start() Pipe opened
7098 12:14:21 12/19/2012 IN TraceC "DBG: relayD ip address is found, IP address: 192.168.0.1 for host: SC-1
7099 12:14:21 12/19/2012 IN TraceC "DBG: RelayDManager::start() RelayD for "TestProf_1" pid: 9082 bound on 192.168.0.1:59383:50886
7100 12:14:21 12/19/2012 IN TraceC "DBG: performActivate: Writing session into file
7101 12:14:21 12/19/2012 IN TraceC "DBG: Done Activating
7102 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestProf_1 is being added to parent directory /storage/no-backup/tracecc-apr9010500
7103 12:14:21 12/19/2012 IN TraceC "DBG: RelayD has been launch for TestProf_1 session after 1 tries to connect to free ports.
7104 12:14:21 12/19/2012 IN TraceC "DBG: relayD ip address is found, IP address: 192.168.0.1 for host: SC-1
7105 12:14:21 12/19/2012 IN TraceC "DBG: performActivateAfterRelayD: Sending commands to the trace_ps.
7106 12:14:21 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-3,traceMId=1, op: 2, addr: 0x7FA4F80008D0
7107 12:14:21 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-4,traceMId=1, op: 2, addr: 0x7FA4F80012C0
7108 12:14:21 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-1,traceMId=1, op: 2, addr: 0x7FA4F8006A30
7109 12:14:21 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-2,traceMId=1, op: 2, addr: 0x7FA4F8006EC0
7110 12:14:21 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
7111 12:14:21 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA4F80008D0
7112 12:14:21 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
7113 12:14:21 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA4F80012C0
7114 12:14:21 12/19/2012 IN TraceP_PL-3 "Activating
7115 12:14:21 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA4F8006A30
7116 12:14:21 12/19/2012 IN TraceP_PL-4 "Activating
7117 12:14:21 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA4F8006EC0
7118 12:14:21 12/19/2012 IN TraceP_SC-1 "Activating
7119 12:14:21 12/19/2012 IN TraceP_SC-2 "Activating
7120 12:14:21 12/19/2012 ER TraceP_PL-3 "Unable to add filter for session TestProf_1. error: 512
7121 12:14:21 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: invoke lttng_create_session for session TestProf_1 with url net://192.168.0.1:59383:50886/./.
7122 12:14:21 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: Invoking lttng_create_handle for session TestProf_1
7123 12:14:21 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: Invoking lttng_set_default_attr for session TestProf_1.
7124 12:14:21 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: Invoking lttng_enable_channel for session TestProf_1
7125 12:14:21 12/19/2012 ER TraceP_PL-4 "Unable to add filter for session TestProf_1. error: 512
7126 12:14:21 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: invoke lttng_create_session for session TestProf_1 with url net://192.168.0.1:59383:50886/./.
7127 12:14:21 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: Invoking lttng_create_handle for session TestProf_1
7128 12:14:21 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: Invoking lttng_set_default_attr for session TestProf_1.
7129 12:14:21 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: Invoking lttng_enable_channel for session TestProf_1
7130 12:14:21 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: Invoking lttng_enable_event_with_filter for session TestProf_1, event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA, with cond ''
7131 12:14:21 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: Invoking lttng_start_tracing, session name TestProf_1
7132 12:14:21 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: Invoking lttng_enable_event_with_filter for session TestProf_1, event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA, with cond ''
7133 12:14:21 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: Invoking lttng_start_tracing, session name TestProf_1
7134 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory PL-3 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1
7135 12:14:21 12/19/2012 ER TraceP_SC-1 "Unable to add filter for session TestProf_1. error: 512
7136 12:14:21 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: invoke lttng_create_session for session TestProf_1 with url net://192.168.0.1:59383:50886/./.
7137 12:14:21 12/19/2012 ER TraceP_SC-2 "Unable to add filter for session TestProf_1. error: 512
7138 12:14:21 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: invoke lttng_create_session for session TestProf_1 with url net://192.168.0.1:59383:50886/./.
7139 12:14:21 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: Invoking lttng_create_handle for session TestProf_1
7140 12:14:21 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: Invoking lttng_set_default_attr for session TestProf_1.
7141 12:14:21 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: Invoking lttng_enable_channel for session TestProf_1
7142 12:14:21 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: Invoking lttng_create_handle for session TestProf_1
7143 12:14:21 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: Invoking lttng_set_default_attr for session TestProf_1.
7144 12:14:21 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: Invoking lttng_enable_channel for session TestProf_1
7145 12:14:21 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: Invoking lttng_enable_event_with_filter for session TestProf_1, event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA, with cond ''
7146 12:14:21 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: Invoking lttng_start_tracing, session name TestProf_1
7147 12:14:21 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: Invoking lttng_enable_event_with_filter for session TestProf_1, event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA, with cond ''
7148 12:14:21 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: Invoking lttng_start_tracing, session name TestProf_1
7149 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory ust is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3
7150 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_Thread1-19569-20121219-121421 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
7151 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust has been deleted, moved, replaced or a delayed creation notification has been received in /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3
7152 12:14:21 12/19/2012 IN TraceC "DBG: TraceCHouseKeeping:directoryDeleteHandler is deleting ust
7153 12:14:21 12/19/2012 IN TraceC "DBG: directoryDeleteHandler : directory ust is being deleted
7154 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3
7155 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_Thread1-19569-20121219-121421 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
7156 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory PL-4 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1
7157 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory ust is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4
7158 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_type1-19676-20121219-121421 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
7159 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust has been deleted, moved, replaced or a delayed creation notification has been received in /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4
7160 12:14:21 12/19/2012 IN TraceC "DBG: TraceCHouseKeeping:directoryDeleteHandler is deleting ust
7161 12:14:21 12/19/2012 IN TraceC "DBG: directoryDeleteHandler : directory ust is being deleted
7162 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4
7163 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_type1-19676-20121219-121421 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
7164 12:14:21 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
7165 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory SC-2 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1
7166 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory ust is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2
7167 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_Fork1-22535-20121219-121421 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
7168 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust has been deleted, moved, replaced or a delayed creation notification has been received in /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2
7169 12:14:21 12/19/2012 IN TraceC "DBG: TraceCHouseKeeping:directoryDeleteHandler is deleting ust
7170 12:14:21 12/19/2012 IN TraceC "DBG: directoryDeleteHandler : directory ust is being deleted
7171 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2
7172 12:14:21 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_Fork1-22535-20121219-121421 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
7173 12:14:21 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-19568-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
7174 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-19578-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
7175 12:14:22 12/19/2012 IN TraceP_SC-1 "DBG: activateSession: Reply recieved for lttng_start_tracing for session TestProf_1.
7176 12:14:22 12/19/2012 IN TraceP_SC-1 "DBG: Return for invocation -3 value: 1, return code: 1 , SA_AIS_OK
7177 12:14:22 12/19/2012 IN TraceP_SC-1 "Activation completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1
7178 12:14:22 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7179 12:14:22 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7180 12:14:22 12/19/2012 IN TraceC "receiveTracePActivateResult result: 1 op_result 1
7181 12:14:22 12/19/2012 NO TraceC "Session TestProf_1 activated.
7182 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Thread1-19678-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
7183 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Thread1-22526-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
7184 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_type1-19567-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
7185 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-19677-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
7186 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-22525-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
7187 12:14:22 12/19/2012 IN TraceP_PL-3 "DBG: activateSession: Reply recieved for lttng_start_tracing for session TestProf_1.
7188 12:14:22 12/19/2012 IN TraceP_PL-3 "DBG: Return for invocation -1 value: 1, return code: 1 , SA_AIS_OK
7189 12:14:22 12/19/2012 IN TraceP_PL-3 "Activation completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1
7190 12:14:22 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7191 12:14:22 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
7192 12:14:22 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7193 12:14:22 12/19/2012 IN TraceC "receiveTracePActivateResult result: 1 op_result 1
7194 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_type1-22524-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
7195 12:14:22 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-19685-20121219-121421 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
7196 12:14:22 12/19/2012 IN TraceP_SC-2 "DBG: activateSession: Reply recieved for lttng_start_tracing for session TestProf_1.
7197 12:14:22 12/19/2012 IN TraceP_SC-2 "DBG: Return for invocation -4 value: 1, return code: 1 , SA_AIS_OK
7198 12:14:22 12/19/2012 IN TraceP_SC-2 "Activation completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1
7199 12:14:22 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7200 12:14:22 12/19/2012 IN TraceP_PL-4 "DBG: activateSession: Reply recieved for lttng_start_tracing for session TestProf_1.
7201 12:14:22 12/19/2012 IN TraceP_PL-4 "DBG: Return for invocation -2 value: 1, return code: 1 , SA_AIS_OK
7202 12:14:22 12/19/2012 IN TraceP_PL-4 "Activation completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1
7203 12:14:22 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7204 12:14:22 12/19/2012 IN TraceC "receiveTracePActivateResult result: 1 op_result 1
7205 12:14:22 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7206 12:14:22 12/19/2012 IN TraceC "receiveTracePActivateResult result: 1 op_result 1
Wed Dec 19 12:14:22 EST 2012
root 7972 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_c
root 7973 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_p
root 9046 26613 0 12:14 pts/0 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 9063 9046 0 12:14 pts/0 00:00:00 lttng-consumerd --verbose -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 9082 7972 2 12:14 ? 00:00:00 lttng-relayd -C tcp://192.168.0.1:59383 -D tcp://192.168.0.1:50886 -o /storage/no-backup/tracecc-apr9010500/TestProf_1
root 21870 1 0 Dec18 ? 00:00:11 /opt/trace_ea/bin/TraceEa
root 21878 21870 0 Dec18 ? 00:00:02 /opt/trace_ea/bin/TraceEa
Wed Dec 19 12:14:22 EST 2012
Allow session to run for 10 sec...
DEBUG1: UST registration received with pid:8518 ppid:1 uid:0 gid:0 sock:16 name:TestApp_Thread1 (version 2.0) [in thread_registration_apps() at main.c:1513]
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:1413]
DEBUG1: UST registration received with pid:8516 ppid:1 uid:0 gid:0 sock:21 name:TestApp_type1 (version 2.0) [in thread_registration_apps() at main.c:1513]
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:1413]
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: UST registration received with pid:8517 ppid:1 uid:0 gid:0 sock:22 name:TestApp_Fork1 (version 2.0) [in thread_registration_apps() at main.c:1513]
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:1413]
DEBUG1: Dispatching UST registration pid:8518 ppid:1 uid:0 gid:0 sock:16 name:TestApp_Thread1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1322]
DEBUG1: UST registration received with pid:8527 ppid:8517 uid:0 gid:0 sock:23 name:TestApp_Fork1 (version 2.0) [in thread_registration_apps() at main.c:1513]
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:1413]
DEBUG1: Dispatching UST registration pid:8516 ppid:1 uid:0 gid:0 sock:21 name:TestApp_type1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1322]
DEBUG1: Dispatching UST registration pid:8517 ppid:1 uid:0 gid:0 sock:22 name:TestApp_Fork1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1322]
DEBUG1: Dispatching UST registration pid:8527 ppid:8517 uid:0 gid:0 sock:23 name:TestApp_Fork1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1322]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1310]
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:1310]
DEBUG3: Created hashtable size 4 at 0x650a70 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:8518 ppid:1 uid:0 gid:0 sock:16 name:TestApp_Thread1 (version 2.0) [in ust_app_register() at ust-app.c:1494]
DEBUG2: UST app PID 8518 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2877]
DEBUG2: UST app global update for app sock 16 for session id 1 [in ust_app_global_update() at ust-app.c:2603]
DEBUG2: UST app pid: 8518 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:1048]
DEBUG3: Created hashtable size 4 at 0x650f60 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:958]
DEBUG2: Channel channel0 not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:987]
DEBUG3: Created hashtable size 4 at 0x658270 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x6587b0 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:373]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:900]
DEBUG2: UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:925]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:407]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:935]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG2: UST app channel channel0 created successfully for pid:8518 and sock:16 [in create_ust_channel() at ust-app.c:786]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA created successfully for pid:8518 [in create_ust_event() at ust-app.c:826]
DEBUG1: Starting tracing for ust app pid 8518 [in ust_app_start_trace() at ust-app.c:2227]
DEBUG2: UST metadata opened for app pid 8518 [in create_ust_app_metadata() at ust-app.c:1350]
DEBUG2: UST metadata stream object created for app pid 8518 [in create_ust_app_metadata() at ust-app.c:1368]
DEBUG2: UST stream 1 ready (handle: 6) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 2 ready (handle: 7) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 3 ready (handle: 8) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 4 ready (handle: 9) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG1: Sending metadata stream fd to consumer on 20 [in ust_consumer_send_session() at ust-consumer.c:330]
DEBUG1: UST consumer sending metadata stream fd [in send_metadata() at ust-consumer.c:223]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: consumer_add_channel 26 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 26, shm_fd -1, wait_fd -1, mmap_len 768, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 26 stream 28 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (key 28, shm_fd 21, wait_fd 22, mmap_len 13056, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name metadata [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Sending streams of channel channel0 to UST consumer [in send_channel_streams() at ust-consumer.c:147]
DEBUG2: Sending channel channel0 to UST consumer [in send_channel() at ust-consumer.c:50]
7207 12:14:23 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory SC-1 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1
7208 12:14:23 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory ust is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1
7209 12:14:23 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_Thread1-8518-20121219-121423 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
7210 12:14:23 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust has been deleted, moved, replaced or a delayed creation notification has been received in /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1
7211 12:14:23 12/19/2012 IN TraceC "DBG: TraceCHouseKeeping:directoryDeleteHandler is deleting ust
7212 12:14:23 12/19/2012 IN TraceC "DBG: directoryDeleteHandler : directory ust is being deleted
7213 12:14:23 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory ust is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1
7214 12:14:23 12/19/2012 IN TraceC "DBG: synchronizeDirectory : directory TestApp_Thread1-8518-20121219-121423 is being added by sync to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
7215 12:14:23 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_type1-8516-20121219-121423 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
DEBUG1: Relayd stream added successfully with handle 61 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (21,22) with relayd id 61 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Metadata event catched in thread [in consumer_thread_metadata_poll() at consumer.c:2118]
DEBUG1: Adding metadata stream 22 to poll set [in consumer_thread_metadata_poll() at consumer.c:2175]
DEBUG3: Adding metadata stream 22 to hash table [in consumer_add_metadata_stream() at consumer.c:1960]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: Metadata poll wait with 2 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: consumer_add_channel 24 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 24, shm_fd -1, wait_fd -1, mmap_len 816, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG3: UST network consumer subdir path: SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ [in send_channel_streams() at ust-consumer.c:173]
DEBUG2: Sending stream 30 of channel channel0 to kernel consumer [in send_channel_stream() at ust-consumer.c:100]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 24 stream 30 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (key 30, shm_fd 21, wait_fd 23, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_0 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 62 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (21,23) with relayd id 62 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 24 stream 32 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (key 32, shm_fd 21, wait_fd 24, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_1 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG3: Adding consumer stream 30 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 2 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Relayd stream added successfully with handle 63 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (21,24) with relayd id 63 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 32 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 3 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 24 stream 34 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (key 34, shm_fd 21, wait_fd 25, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_2 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 64 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (21,25) with relayd id 64 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 34 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 4 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 24 stream 36 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (key 36, shm_fd 21, wait_fd 26, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_3 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 65 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Thread1-8518-20121219-121423/ (21,26) with relayd id 65DEBUG2: UST trace started for app pid 8518 [in ust_app_global_update() at ust-app.c:2669]
DEBUG1: Apps with sock 16 added to poll set [in thread_manage_apps() at main.c:1236]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1135]
DEBUG3: Created hashtable size 4 at 0x664d70 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:8516 ppid:1 uid:0 gid:0 sock:21 name:TestApp_type1 (version 2.0) [in ust_app_register() at ust-app.c:1494]
DEBUG2: UST app PID 8516 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2877]
DEBUG2: UST app global update for app sock 21 for session id 1 [in ust_app_global_update() at ust-app.c:2603]
DEBUG2: UST app pid: 8516 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:1048]
DEBUG3: Created hashtable size 4 at 0x6662e0 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:958]
DEBUG2: Channel channel0 not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:987]
DEBUG3: Created hashtable size 4 at 0x666ad0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x667010 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:373]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:900]
DEBUG2: UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:925]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:407]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:935]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG2: UST app channel channel0 created successfully for pid:8516 and sock:21 [in create_ust_channel() at ust-app.c:786]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA created successfully for pid:8516 [in create_ust_event() at ust-app.c:826]
DEBUG1: Starting tracing for ust app pid 8516 [in ust_app_start_trace() at ust-app.c:2227]
DEBUG2: UST metadata opened for app pid 8516 [in create_ust_app_metadata() at ust-app.c:1350]
DEBUG2: UST metadata stream object created for app pid 8516 [in create_ust_app_metadata() at ust-app.c:1368]
DEBUG2: UST stream 1 ready (handle: 6) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 2 ready (handle: 7) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 3 ready (handle: 8) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 4 ready (handle: 9) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG1: Sending metadata stream fd to consumer on 20 [in ust_consumer_send_session() at ust-consumer.c:330]
DEBUG1: UST consumer sending metadata stream fd [in send_metadata() at ust-consumer.c:223]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: consumer_add_channel 40 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 40, shm_fd -1, wait_fd -1, mmap_len 768, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 40 stream 42 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (key 42, shm_fd 21, wait_fd 27, mmap_len 13056, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name metadata [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Sending streams of channel channel0 to UST consumer [in send_channel_streams() at ust-consumer.c:147]
DEBUG2: Sending channel channel0 to UST consumer [in send_channel() at ust-consumer.c:50]
DEBUG1: Relayd stream added successfully with handle 66 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (21,27) with relayd id 66 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: Metadata event catched in thread [in consumer_thread_metadata_poll() at consumer.c:2118]
DEBUG1: Adding metadata stream 27 to poll set [in consumer_thread_metadata_poll() at consumer.c:2175]
DEBUG3: Adding metadata stream 27 to hash table [in consumer_add_metadata_stream() at consumer.c:1960]
DEBUG1: consumer_add_channel 38 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Metadata poll wait with 3 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG1: Allocated channel (key 38, shm_fd -1, wait_fd -1, mmap_len 816, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG3: UST network consumer subdir path: SC-1/.//ust/TestApp_type1-8516-20121219-121423/ [in send_channel_streams() at ust-consumer.c:173]
DEBUG2: Sending stream 44 of channel channel0 to kernel consumer [in send_channel_stream() at ust-consumer.c:100]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 38 stream 44 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (key 44, shm_fd 21, wait_fd 28, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_0 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 67 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (21,28) with relayd id 67 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 38 stream 46 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (key 46, shm_fd 21, wait_fd 29, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_1 [in relayd_add_stream() at relayd.c:167]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 44 [in consumer_add_stream() at consumer.c:616]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 6 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Relayd stream added successfully with handle 68 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (21,29) with relayd id 68 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG1: Consumer command ADD_STREAM chan 38 stream 48 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (key 48, shm_fd 21, wait_fd 30, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG3: Adding consumer stream 46 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Relayd adding stream for channel name channel0_2 [in relayd_add_stream() at relayd.c:167]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 7 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 69 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (21,30) with relayd id 69 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 48 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 8 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 38 stream 50 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (key 50, shm_fd 21, wait_fd 31, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_3 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 70 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_type1-8516-20121219-121423/ (21,31) with relayd id 70 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in coDEBUG1: Apps with sock 21 added to poll set [in thread_manage_apps() at main.c:1236]
DEBUG1: Apps thread polling on 4 fds [in tDEBUG1: consumer_data_pipe wake up [DEBUG3: Created hashtable size 4 at 0x66d9c0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:8517 DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumDEBUG2: Shadow copy of session handle -1 [in shadow_copy_session() at ust-app.c:958]
DEBUG2: Channel channel0 not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:987]
DEBUG3: Created hashtable size 4 at 0x66f760 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x66fca0 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:373]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:900]
DEBUG2: UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:925]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:407]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:935]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG2: UST app channel channel0 created successfully for pid:8517 and sock:22 [in create_ust_channel() at ust-app.c:786]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA created successfully for pid:8517 [in create_ust_event() at ust-app.c:826]
DEBUG1: Starting tracing for ust app pid 8517 [in ust_app_start_trace() at ust-app.c:2227]
DEBUG2: UST metadata opened for app pid 8517 [in create_ust_app_metadata() at ust-app.c:1350]
DEBUG2: UST metadata stream object created for app pid 8517 [in create_ust_app_metadata() at ust-app.c:1368]
DEBUG2: UST stream 1 ready (handle: 6) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 2 ready (handle: 7) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 3 ready (handle: 8) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 4 ready (handle: 9) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG1: Sending metadata stream fd to consumer on 20 [in ust_consumer_send_session() at ust-consumer.c:330]
DEBUG1: UST consumer sending metadata stream fd [in send_metadata() at ust-consumer.c:223]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: consumer_add_channel 54 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 54, shm_fd -1, wait_fd -1, mmap_len 768, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 54 stream 56 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (key 56, shm_fd 21, wait_fd 32, mmap_len 13056, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name metadata [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Sending streams of channel channel0 to UST consumer [in send_channel_streams() at ust-consumer.c:147]
DEBUG2: Sending channel channel0 to UST consumer [in send_channel() at ust-consumer.c:50]
DEBUG1: Relayd stream added successfully with handle 71 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (21,32) with relayd id 71 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: Metadata event catched in thread [in consumer_thread_metadata_poll() at consumer.c:2118]
DEBUG1: Adding metadata stream 32 to poll set [in consumer_thread_metadata_poll() at consumer.c:2175]
DEBUG3: Adding metadata stream 32 to hash table [in consumer_add_metadata_stream() at consumer.c:1960]
DEBUG1: Metadata poll wait with 4 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG1: consumer_add_channel 52 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 52, shm_fd -1, wait_fd -1, mmap_len 816, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG3: UST network consumer subdir path: SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ [in send_channel_streams() at ust-consumer.c:173]
DEBUG2: Sending stream 58 of channel channel0 to kernel consumer [in send_channel_stream() at ust-consumer.c:100]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 52 stream 58 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (key 58, shm_fd 21, wait_fd 33, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_0 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 72 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (21,33) with relayd id 72 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 58 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 10 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 52 stream 60 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (key 60, shm_fd 21, wait_fd 34, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_1 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 73 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (21,34) with relayd id 73 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 60 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 34 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 11 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 52 stream 62 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (key 62, shm_fd 21, wait_fd 35, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_2 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 74 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (21,35) with relayd id 74 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 62 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 34 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 35 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 12 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 52 stream 64 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (key 64, shm_fd 21, wait_fd 36, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_3 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 75 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8517-20121219-121423/ (21,36) with relayd id 75 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in coDEBUG1: Apps with sock 22 added to poll set [in thread_manage_apps() at main.c:1236]
DEBUG1: Apps thread polling on 5 fds [in thread_manage_apps() at main.c:1135]
DEBUG3: Created hashtable size 4 at 0x6766c0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:8527 ppid:8517 uid:0 gid:0 sock:23 name:TestApp_Fork1 (version 2.0) [in ust_app_register() at ust-app.c:1494]
DEBUG2: UST app PID 8527 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2877]
DEBUG2: UST app global update for app sock 23 for session id 1 [in ust_app_global_update() at ust-app.c:2603]
DEBUG2: UST app pid: 8527 session id 1 not found, creating it [in create_ust_app_session() at ust-app.c:1048]
DEBUG3: Created hashtable size 4 at 0x677c50 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:958]
DEBUG2: Channel channel0 not found on shadow session copy, creating it [in shadow_copy_session() at ust-app.c:987]
DEBUG3: Created hashtable size 4 at 0x678420 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x678960 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:373]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:900]
DEBUG2: UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA not found on shadow copy channel [in shadow_copy_channel() at ust-app.c:925]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:407]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:935]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:1077]
DEBUG2: UST app channel channel0 created successfully for pid:8527 and sock:23 [in create_ust_channel() at ust-app.c:786]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA created successfully for pid:8527 [in create_ust_event() at ust-app.c:826]
DEBUG1: Starting tracing for ust app pid 8527 [in ust_app_start_trace() at ust-app.c:2227]
DEBUG2: UST metadata opened for app pid 8527 [in create_ust_app_metadata() at ust-app.c:1350]
DEBUG2: UST metadata stream object created for app pid 8527 [in create_ust_app_metadata() at ust-app.c:1368]
DEBUG2: UST stream 1 ready (handle: 6) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 2 ready (handle: 7) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 3 ready (handle: 8) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG2: UST stream 4 ready (handle: 9) [in ust_app_start_trace() at ust-app.c:2315]
DEBUG1: Sending metadata stream fd to consumer on 20 [in ust_consumer_send_session() at ust-consumer.c:330]
DEBUG1: UST consumer sending metadata stream fd [in send_metadata() at ust-consumer.c:223]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: consumer_add_channel 68 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 68, shm_fd -1, wait_fd -1, mmap_len 768, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 68 stream 70 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (key 70, shm_fd 21, wait_fd 37, mmap_len 13056, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name metadata [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 76 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (21,37) with relayd id 76 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding channel [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:144]
DEBUG1: Metadata event catched in thread [in consumer_thread_metadata_poll() at consumer.c:2118]
DEBUG1: Adding metadata stream 37 to poll set [in consumer_thread_metadata_poll() at consumer.c:2175]
DEBUG3: Adding metadata stream 37 to hash table [in consumer_add_metadata_stream() at consumer.c:1960]
DEBUG1: Metadata poll wait with 5 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG1: consumer_add_channel 66 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:176]
DEBUG1: Allocated channel (key 66, shm_fd -1, wait_fd -1, mmap_len 816, max_sb_size 4096) [in consumer_allocate_channel() at consumer.c:914]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG3: UST network consumer subdir path: SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ [in send_channel_streams() at ust-consumer.c:173]
DEBUG2: Sending stream 72 of channel channel0 to kernel consumer [in send_channel_stream() at ust-consumer.c:100]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: Consumer command ADD_STREAM chan 66 stream 72 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (key 72, shm_fd 21, wait_fd 38, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_0 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 77 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (21,38) with relayd id 77 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 72 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 38 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 34 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 36 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 35 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 14 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 66 stream 74 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (key 74, shm_fd 21, wait_fd 39, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_1 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 78 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (21,39) with relayd id 78 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 74 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 38 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 34 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 36 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 35 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 39 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 15 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 66 stream 76 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (key 76, shm_fd 21, wait_fd 40, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_2 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 79 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (21,40) with relayd id 79 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST Consumer adding stream [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:207]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 76 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 38 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 34 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 36 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 35 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 40 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 39 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 16 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Consumer command ADD_STREAM chan 66 stream 78 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:240]
DEBUG3: Allocated stream SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (key 78, shm_fd 21, wait_fd 41, mmap_len 21888, out_fd -1, net_seq_idx 2, session_id 1 [in consumer_allocate_stream() at consumer.c:592]
DEBUG1: Relayd adding stream for channel name channel0_3 [in relayd_add_stream() at relayd.c:167]
DEBUG3: Relayd sending command 1 of size 4384 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 12 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd stream added successfully with handle 80 [in relayd_add_stream() at relayd.c:199]
DEBUG1: UST consumer ADD_STREAM SC-1/.//ust/TestApp_Fork1-8527-20121219-121423/ (21,41) with relayd id 80 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:323]
DEBUG1: received fds on sock [in coDEBUG1: Apps with sock 23 added to poll set [in thDEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2367]
DEBUG3: Adding consumer stream 78 [in consumer_add_stream() at consumer.c:616]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 38 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 34 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 41 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 36 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 35 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 40 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 39 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 33 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 17 fd [in consumer_thread_data_poll() at consumer.c:2341]
7216 12:14:23 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-8517-20121219-121423 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
7217 12:14:23 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestApp_Fork1-8527-20121219-121423 is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health state current 494, last 10, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 5, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: Normal read on fd 29 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 29, stream key: 46) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 4042 (len 4042) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: polling on 17 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Health state current 502, last 10, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 5, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
Wed Dec 19 12:14:32 EST 2012
root 7972 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_c
root 7973 1 0 12:11 ? 00:00:00 /opt/trace/sbin/trace_p
root 9046 26613 0 12:14 pts/0 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 9063 9046 0 12:14 pts/0 00:00:00 lttng-consumerd --verbose -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 9082 7972 0 12:14 ? 00:00:00 lttng-relayd -C tcp://192.168.0.1:59383 -D tcp://192.168.0.1:50886 -o /storage/no-backup/tracecc-apr9010500/TestProf_1
root 21870 1 0 Dec18 ? 00:00:11 /opt/trace_ea/bin/TraceEa
root 21878 21870 0 Dec18 ? 00:00:02 /opt/trace_ea/bin/TraceEa
Wed Dec 19 12:14:32 EST 2012
Printing Session
####################
Wed Dec 19 12:14:32 EST 2012
errors : NoError;
logLevelDefault : TRACE_DEBUG_SYSTEM(7)
startTime : 12/19/12T12:14:21-0500
state : ACTIVE
stopTime : ""
traceExpressions : com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA,TRACE_DEBUG_MODULE(10)
traceProfileId : TestProf
--------------------------------
progress : ""
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Fork1-8527-20121219-121423
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Fork1-8517-20121219-121423
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Thread1-8518-20121219-121423
8.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_type1-8516-20121219-121423
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
28K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1
8.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_type1-19676-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Thread1-19678-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Fork1-19677-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Fork1-19685-20121219-121421
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
28K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Fork1-19568-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Fork1-19578-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Thread1-19569-20121219-121421
8.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_type1-19567-20121219-121421
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
28K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3
8.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_type1-22524-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Fork1-22525-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Thread1-22526-20121219-121421
4.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Fork1-22535-20121219-121421
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
28K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2
120K /storage/no-backup/tracecc-apr9010500/TestProf_1
Wed Dec 19 12:14:32 EST 2012
Printing Ports while Session is active
####################
tcp 0 0 192.168.0.1:50886 0.0.0.0:* LISTEN 0 617593 9082/lttng-relayd
tcp 0 0 192.168.0.1:59383 0.0.0.0:* LISTEN 0 617592 9082/lttng-relayd
tcp 0 0 192.168.0.1:59383 192.168.0.2:47024 ESTABLISHED 0 617620 9082/lttng-relayd
tcp 0 0 192.168.0.1:50886 192.168.0.2:46572 ESTABLISHED 0 617621 9082/lttng-relayd
tcp 0 0 192.168.0.1:50886 192.168.0.1:60189 ESTABLISHED 0 617623 9082/lttng-relayd
tcp 0 0 192.168.0.1:55860 192.168.0.1:59383 ESTABLISHED 0 617618 9063/lttng-consumer
tcp 0 0 192.168.0.1:59383 192.168.0.1:55860 ESTABLISHED 0 617619 9082/lttng-relayd
tcp 0 0 192.168.0.1:50886 192.168.0.3:38854 ESTABLISHED 0 617611 9082/lttng-relayd
tcp 0 0 192.168.0.1:59383 192.168.0.4:60659 ESTABLISHED 0 617612 9082/lttng-relayd
tcp 0 0 192.168.0.1:60189 192.168.0.1:50886 ESTABLISHED 0 616102 9063/lttng-consumer
tcp 0 0 192.168.0.1:59383 192.168.0.3:33850 ESTABLISHED 0 617610 9082/lttng-relayd
tcp 0 0 192.168.0.1:50886 192.168.0.4:45802 ESTABLISHED 0 617613 9082/lttng-relayd
Wed Dec 19 12:14:32 EST 2012
Deactivating Profile
####################
Wed Dec 19 12:14:32 EST 2012
Dec 19 12:14:32 SC-1 osafimmnd[6451]: Ccb 572 COMMITTED (TraceC)
Dec 19 12:14:32 PL-4 osafimmnd[4935]: Ccb 572 COMMITTED (TraceC)
Dec 19 12:14:32 PL-3 osafimmnd[4905]: Ccb 572 COMMITTED (TraceC)
Dec 19 12:14:32 SC-2 osafimmnd[5121]: Ccb 572 COMMITTED (TraceC)
Dec 19 12:14:32 SC-1 osafimmnd[6451]: Ccb 573 COMMITTED (TraceC)
Dec 19 12:14:32 PL-3 osafimmnd[4905]: Ccb 573 COMMITTED (TraceC)
Dec 19 12:14:32 PL-4 osafimmnd[4935]: Ccb 573 COMMITTED (TraceC)
Dec 19 12:14:32 SC-2 osafimmnd[5121]: Ccb 573 COMMITTED (TraceC)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 13 [in process_client_msg() at main.c:2204]
DEBUG1: Counting number of available session for UID 0 GID 0 [in lttng_sessions_count() at main.c:2175]
DEBUG1: Getting all available session for UID 0 GID 0 [in cmd_list_lttng_sessions() at cmd.c:2074]
DEBUG1: Sending response (size: 4388, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 17 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2275]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG1: Stopping all UST traces [in ust_app_stop_trace_all() at ust-app.c:2544]
DEBUG1: Stopping tracing for ust app pid 8517 [in ust_app_stop_trace() at ust-app.c:2386]
DEBUG1: Stopping tracing for ust app pid 8518 [in ust_app_stop_trace() at ust-app.c:2386]
DEBUG1: Stopping tracing for ust app pid 8527 [in ust_app_stop_trace() at ust-app.c:2386]
DEBUG1: Stopping tracing for ust app pid 8516 [in ust_app_stop_trace() at ust-app.c:2386]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 24 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2275]
DEBUG2: Trying to find session by name TestProf_1 [in session_find_by_name() at session.c:122]
DEBUG3: Consumer data pending for id 1 [in consumer_is_data_pending() at consumer.c:784]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST consumer data pending command for id 1 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:372]
DEBUG1: Consumer data pending command on session id 1 [in consumer_data_pending() at consumer.c:2956]
DEBUG1: Relayd begin data pending [in relayd_begin_data_pending() at relayd.c:522]
DEBUG3: Relayd sending command 10 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd checking quiescent control state [in relayd_quiescent_control() at relayd.c:478]
DEBUG3: Relayd sending command 9 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 62 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 62 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 63 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 63 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 64 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 64 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 65 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 65 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd checking quiescent control state [in relayd_quiescent_control() at relayd.c:478]
DEBUG3: Relayd sending command 9 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 67 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 67 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 68 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 68 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 69 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 69 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 70 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 70 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd checking quiescent control state [in relayd_quiescent_control() at relayd.c:478]
DEBUG3: Relayd sending command 9 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 72 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 72 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 73 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 73 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 74 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 74 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 75 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 75 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd checking quiescent control state [in relayd_quiescent_control() at relayd.c:478]
DEBUG3: Relayd sending command 9 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 77 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 77 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 78 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 78 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 79 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 79 [in relayd_data_pending() at relayd.c:459]
DEBUG1: UST consumer checking data pending [in lttng_ustconsumer_data_pending() at ust-consumer.c:605]
DEBUG1: Relayd data pending for stream id 80 [in relayd_data_pending() at relayd.c:430]
DEBUG3: Relayd sending command 8 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd data is NOT pending for stream id 80 [in relayd_data_pending() at relayd.c:459]
DEBUG1: Relayd end data pending [in relayd_end_data_pending() at relayd.c:569]
DEBUG3: Relayd sending command 11 of size 32 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd end data pending is data inflight: 0 [in relayd_end_data_pending() at relayd.c:593]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG1: Consumer data pending ret 0 [in consumer_is_data_pending() at consumer.c:820]
DEBUG1: Sending response (size: 16, retcode: Unknown error code) [in thread_manage_clients() at main.c:3329]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2204]
DEBUG1: Getting session TestProf_1 by name [in process_client_msg() at main.c:2275]
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:700]
DEBUG2: Sending destroy relayd command to consumer... [in consumer_send_destroy_relayd() at consumer.c:79]
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2610]
DEBUG1: UST consumer destroying relayd 2 [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:331]
DEBUG1: received fds on sock [in consumer_thread_sessiond_poll() at consumer.c:2628]
DEBUG2: Consumer send destroy relayd command done [in consumer_send_destroy_relayd() at consumer.c:102]
DEBUG1: Destroy all UST traces [in ust_app_destroy_trace_all() at ust-app.c:2570]
DEBUG1: Destroy tracing for ust app pid 8517 [in destroy_trace() at ust-app.c:2469]
DEBUG2: Trace UST destroy metadata 4 [in trace_ust_destroy_metadata() at trace-ust.c:586]
DEBUG1: Destroy tracing for ust app pid 8518 [in destroy_trace() at ust-app.c:2469]
DEBUG2: Trace UST destroy metadata 4 [in trace_ust_destroy_metadata() at trace-ust.c:586]
DEBUG1: Destroy tracing for ust app pid 8527 [in destroy_trace() at ust-app.c:2469]
DEBUG2: Trace UST destroy metadata 4 [in trace_ust_destroy_metadata() at trace-ust.c:586]
DEBUG1: Destroy tracing for ust app pid 8516 [in destroy_trace() at ust-app.c:2469]
DEBUG2: Trace UST destroy metadata 4 [in trace_ust_destroy_metadata() at trace-ust.c:586]
DEBUG2: Trace UST destroy session 1 [in trace_ust_destroy_session() at trace-ust.c:668]
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:3329]
DEBUG2: Trace destroy UST channel channel0 [in trace_ust_destroy_channel() at trace-ust.c:551]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
d_data_poll() at consumer.c:2473]
DEBUG1: Metadata stream id 71 with padding 1706 written before data [in write_relayd_metadata_id() at consumer.c:1325]
DEBUG1: Consumer mmap write() ret 2390 (len 2390) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: fd 35 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 35 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 33 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 33 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: polling on 17 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: In read_subbuffer (wait_fd: 32, stream key: 56) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG3: Consumer delete metadata stream 32 [in consumer_del_metadata_stream() at consumer.c:1835]
DEBUG1: poll num_rdy : 16 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: Normal read on fd 34 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 34, stream key: 60) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Relayd closing stream id 71 [in relayd_send_close_stream() at relayd.c:381]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 36 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 36, stream key: 64) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 35 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 35, stream key: 62) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 33 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 33, stream key: 58) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: fd 28 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 28 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 38 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 38 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 29 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 29 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 34 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 41 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 41 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 36 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 26 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 26 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 35 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 25 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 25 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 40 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 40 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 23 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 23 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 39 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 39 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 31 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 31 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 24 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 24 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: fd 30 is hup|err|nval. Attempting flush and read. [in consumer_thread_data_poll() at consumer.c:2462]
DEBUG1: Polling fd 30 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 33 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Relayd close stream id 71 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 54 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Metadata poll wait with 4 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG1: polling on 17 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: poll num_rdy : 16 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: Normal read on fd 28 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 28, stream key: 44) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 38 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 38, stream key: 72) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 29 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 29, stream key: 46) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Metadata event catched in thread [in consumer_thread_metadata_poll() at consumer.c:2118]
DEBUG1: Metadata fd 22 is hup|err. [in consumer_thread_metadata_poll() at consumer.c:2205]
DEBUG1: Attempting to flush and consume the UST buffers [in consumer_thread_metadata_poll() at consumer.c:2209]
DEBUG1: In read_subbuffer (wait_fd: 22, stream key: 28) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Relayd sending metadata of size 2404 [in relayd_send_metadata() at relayd.c:287]
DEBUG3: Relayd sending command 6 of size 24 [in send_command() at relayd.c:74]
DEBUG1: Metadata stream id 61 with padding 1704 written before data [in write_relayd_metadata_id() at consumer.c:1325]
DEBUG1: Consumer mmap write() ret 2392 (len 2392) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: In read_subbuffer (wait_fd: 22, stream key: 28) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG3: Consumer delete metadata stream 22 [in consumer_del_metadata_stream() at consumer.c:1835]
DEBUG1: Consumer mmap write() ret 2213 (len 2213) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Relayd closing stream id 61 [in relayd_send_close_stream() at relayd.c:381]
DEBUG1: Normal read on fd 34 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 34, stream key: 60) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Normal read on fd 41 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 41, stream key: 78) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 36 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 36, stream key: 64) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 26 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 26, stream key: 36) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 35 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 35, stream key: 62) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 25 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 25, stream key: 34) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 40 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 40, stream key: 76) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 23 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 23, stream key: 30) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 39 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 39, stream key: 74) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 31 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 31, stream key: 50) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 24 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 24, stream key: 32) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 30 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 30, stream key: 48) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG3: Relayd sending data header of size 32 [in relayd_send_data_hdr() at relayd.c:345]
DEBUG1: Consumer mmap write() ret 68 (len 68) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: Normal read on fd 33 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 33, stream key: 58) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Polling fd 28 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 38 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 29 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 34 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 34 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd close stream id 61 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 26 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Metadata fd 37 is hup|err. [in consumer_thread_metadata_poll() at consumer.c:2205]
DEBUG1: Attempting to flush and consume the UST buffers [in consumer_thread_metadata_poll() at consumer.c:2209]
DEBUG1: In read_subbuffer (wait_fd: 37, stream key: 70) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Relayd closing stream id 73 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 73 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 41 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 36 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 36 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 75 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 75 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 26 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 35 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 35 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 74 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 74 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 25 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 40 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 23 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 39 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 31 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 24 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 30 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Polling fd 33 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 33 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 72 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 72 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 52 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: Active FD 28 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 38 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 29 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 41 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 26 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 25 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 40 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 23 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 39 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 31 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 24 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: Active FD 30 [in consumer_update_poll_array() at consumer.c:980]
DEBUG1: polling on 13 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: poll num_rdy : 12 [in consumer_thread_data_poll() at consumer.c:2343]
DEBUG1: Normal read on fd 28 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 28, stream key: 44) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 38 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 38, stream key: 72) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 29 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 29, stream key: 46) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 41 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 41, stream key: 78) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 26 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 26, stream key: 36) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 25 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 25, stream key: 34) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 40 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 40, stream key: 76) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 23 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 23, stream key: 30) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 39 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 39, stream key: 74) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 31 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 31, stream key: 50) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 24 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 24, stream key: 32) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Normal read on fd 30 [in consumer_thread_data_poll() at consumer.c:2439]
DEBUG1: In read_subbuffer (wait_fd: 30, stream key: 48) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG1: Polling fd 28 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 28 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 67 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 67 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 38 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 38 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 77 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 77 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 29 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 29 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 68 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 68 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 41 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 41 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 80 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 80 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 26 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 26 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 65 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 65 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 25 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 25 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 64 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 64 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 40 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 40 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 79 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 79 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 23 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 23 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 62 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 62 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 39 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 39 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 78 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 78 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 66 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Polling fd 31 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 31 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 70 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 70 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Polling fd 24 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 24 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 63 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 63 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 24 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Polling fd 30 tells it has hung up. [in consumer_thread_data_poll() at consumer.c:2473]
DEBUG1: Consumer del stream 30 [in consumer_del_stream() at consumer.c:401]
DEBUG1: Relayd closing stream id 69 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 69 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 38 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:964]
DEBUG1: polling on 1 fd [in consumer_thread_data_poll() at consumer.c:2341]
DEBUG1: Relayd sending metadata of size 2402 [in relayd_send_metadata() at relayd.c:287]
DEBUG3: Relayd sending command 6 of size 24 [in send_command() at relayd.c:74]
DEBUG1: Metadata stream id 76 with padding 1706 written before data [in write_relayd_metadata_id() at consumer.c:1325]
DEBUG1: Consumer mmap write() ret 2390 (len 2390) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: In read_subbuffer (wait_fd: 37, stream key: 70) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG3: Consumer delete metadata stream 37 [in consumer_del_metadata_stream() at consumer.c:1835]
DEBUG1: Relayd closing stream id 76 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 76 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer delete channel key 68 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Metadata fd 27 is hup|err. [in consumer_thread_metadata_poll() at consumer.c:2205]
DEBUG1: Attempting to flush and consume the UST buffers [in consumer_thread_metadata_poll() at consumer.c:2209]
DEBUG1: In read_subbuffer (wait_fd: 27, stream key: 42) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Relayd sending metadata of size 2849 [in relayd_send_metadata() at relayd.c:287]
DEBUG3: Relayd sending command 6 of size 24 [in send_command() at relayd.c:74]
DEBUG1: Metadata stream id 66 with padding 1259 written before data [in write_relayd_metadata_id() at consumer.c:1325]
DEBUG1: Consumer mmap write() ret 2837 (len 2837) [in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1436]
DEBUG1: In read_subbuffer (wait_fd: 27, stream key: 42) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:489]
DEBUG1: Reserving sub buffer failed (everything is normal, it is due to concurrency) [in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:517]
DEBUG3: Consumer delete metadata stream 27 [in consumer_del_metadata_stream() at consumer.c:1835]
DEBUG1: Relayd closing stream id 66 [in relayd_send_close_stream() at relayd.c:381]
DEBUG3: Relayd sending command 7 of size 40 [in send_command() at relayd.c:74]
DEBUG3: Relayd waiting for reply of size 4 [in recv_reply() at relayd.c:90]
DEBUG1: Relayd close stream id 66 successfully [in relayd_send_close_stream() at relayd.c:409]
DEBUG1: Consumer destroy and close relayd socket pair [in destroy_relayd() at consumer.c:240]
DEBUG1: Consumer delete channel key 40 [in consumer_del_channel() at consumer.c:822]
DEBUG1: Metadata poll wait with 1 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2116]
DEBUG3: Relayd closing socket 18 [in relayd_close() at relayd.c:328]
DEBUG3: Relayd closing socket 20 [in relayd_close() at relayd.c:328]
7218 12:14:32 12/19/2012 IN TraceC "DBG: Deactivating
7219 12:14:32 12/19/2012 IN TraceC "DBG: Getting Session "traceSessionRecordingId=TestProf_1,traceMId=1" from Registries

7220 12:14:32 12/19/2012 IN TraceC "DBG: Checking if the current state of Session "traceSessionRecordingId=TestProf_1,traceMId=1" is valid

7221 12:14:32 12/19/2012 NO TraceC "Deactivating session TestProf_1.
7222 12:14:32 12/19/2012 IN TraceC "DBG: update Async for deactivate - first time
7223 12:14:32 12/19/2012 IN TraceC "DBG: sending deactivate requests to all traceP's

7224 12:14:32 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-3,traceMId=1, op: 3, addr: 0x7FA5000034E0
7225 12:14:32 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-4,traceMId=1, op: 3, addr: 0x7FA500003610
7226 12:14:32 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-1,traceMId=1, op: 3, addr: 0x7FA500003760
7227 12:14:32 12/19/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-2,traceMId=1, op: 3, addr: 0x7FA5000038B0
7228 12:14:32 12/19/2012 IN TraceC "DBG: Return for invocation 1 value: 1, return code: 1 , SA_AIS_OK
7229 12:14:32 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
7230 12:14:32 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA5000034E0
7231 12:14:32 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
7232 12:14:32 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA500003610
7233 12:14:32 12/19/2012 IN TraceP_PL-3 "Deactivating
7234 12:14:32 12/19/2012 IN TraceP_PL-3 "DBG: hasSession: Invoke lttng_list_session.
7235 12:14:32 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA500003760
7236 12:14:32 12/19/2012 IN TraceP_PL-3 "DBG: hasSession: Reply recieved from lttng_list_session with count 1
7237 12:14:32 12/19/2012 IN TraceP_PL-3 "DBG: deactivateSession: Invoke lttng_stop_tracing for session TestProf_1
7238 12:14:32 12/19/2012 IN TraceP_PL-4 "Deactivating
7239 12:14:32 12/19/2012 IN TraceP_PL-4 "DBG: hasSession: Invoke lttng_list_session.
7240 12:14:32 12/19/2012 IN TraceC "DBG: Invoking admin op 0x7FA5000038B0
7241 12:14:32 12/19/2012 IN TraceP_PL-4 "DBG: hasSession: Reply recieved from lttng_list_session with count 1
7242 12:14:32 12/19/2012 IN TraceP_PL-4 "DBG: deactivateSession: Invoke lttng_stop_tracing for session TestProf_1
7243 12:14:32 12/19/2012 IN TraceP_SC-1 "Deactivating
7244 12:14:32 12/19/2012 IN TraceP_SC-1 "DBG: hasSession: Invoke lttng_list_session.
7245 12:14:32 12/19/2012 IN TraceP_SC-1 "DBG: hasSession: Reply recieved from lttng_list_session with count 1
7246 12:14:32 12/19/2012 IN TraceP_SC-1 "DBG: deactivateSession: Invoke lttng_stop_tracing for session TestProf_1
7247 12:14:32 12/19/2012 IN TraceP_SC-2 "Deactivating
7248 12:14:32 12/19/2012 IN TraceP_SC-2 "DBG: hasSession: Invoke lttng_list_session.
7249 12:14:32 12/19/2012 IN TraceP_SC-2 "DBG: hasSession: Reply recieved from lttng_list_session with count 1
7250 12:14:32 12/19/2012 IN TraceP_SC-2 "DBG: deactivateSession: Invoke lttng_stop_tracing for session TestProf_1
7251 12:14:32 12/19/2012 IN TraceP_PL-3 "DBG: deactivateSession: Invoke lttng_destroy_session TestProf_1.
7252 12:14:32 12/19/2012 IN TraceP_PL-3 "DBG: deactivateSession: Reply recieved for lttng_destroy_session for session TestProf_1
7253 12:14:32 12/19/2012 IN TraceP_PL-3 "DBG: Return for invocation -5 value: 1, return code: 1 , SA_AIS_OK
7254 12:14:32 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7255 12:14:32 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7256 12:14:32 12/19/2012 IN TraceC "receiveTracePDeactivateResult result: 1 op_result 1
7257 12:14:32 12/19/2012 IN TraceP_PL-4 "DBG: deactivateSession: Invoke lttng_destroy_session TestProf_1.
7258 12:14:32 12/19/2012 IN TraceP_PL-4 "DBG: deactivateSession: Reply recieved for lttng_destroy_session for session TestProf_1
7259 12:14:32 12/19/2012 IN TraceP_PL-4 "DBG: Return for invocation -6 value: 1, return code: 1 , SA_AIS_OK
7260 12:14:32 12/19/2012 IN TraceP_PL-3 "Deactivation was completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1.
7261 12:14:32 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7262 12:14:32 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7263 12:14:32 12/19/2012 IN TraceC "receiveTracePDeactivateResult result: 1 op_result 1
7264 12:14:32 12/19/2012 IN TraceP_PL-4 "Deactivation was completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1.
7265 12:14:32 12/19/2012 IN TraceP_SC-1 "DBG: deactivateSession: Invoke lttng_destroy_session TestProf_1.
7266 12:14:32 12/19/2012 IN TraceP_SC-2 "DBG: deactivateSession: Invoke lttng_destroy_session TestProf_1.
7267 12:14:32 12/19/2012 IN TraceP_SC-2 "DBG: deactivateSession: Reply recieved for lttng_destroy_session for session TestProf_1
7268 12:14:32 12/19/2012 IN TraceP_SC-2 "DBG: Return for invocation -8 value: 1, return code: 1 , SA_AIS_OK
7269 12:14:32 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7270 12:14:32 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7271 12:14:32 12/19/2012 IN TraceC "receiveTracePDeactivateResult result: 1 op_result 1
7272 12:14:32 12/19/2012 IN TraceP_SC-2 "Deactivation was completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1.
7273 12:14:33 12/19/2012 IN TraceP_SC-1 "DBG: deactivateSession: Reply recieved for lttng_destroy_session for session TestProf_1
7274 12:14:33 12/19/2012 IN TraceP_SC-1 "DBG: Return for invocation -7 value: 1, return code: 1 , SA_AIS_OK
7275 12:14:33 12/19/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
7276 12:14:33 12/19/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
7277 12:14:33 12/19/2012 IN TraceC "receiveTracePDeactivateResult result: 1 op_result 1
7278 12:14:33 12/19/2012 IN TraceC "deactivateSessionOnTracePsComplete
7279 12:14:33 12/19/2012 IN TraceC "DBG: Waiting 40 sec before killing relayd
7280 12:14:33 12/19/2012 IN TraceP_SC-1 "Deactivation was completed successfully for session traceSessionRecordingId=TestProf_1,traceMId=1.
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Health state current 598, last 10, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 5, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Health state current 606, last 10, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 5, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 614, last 10, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 5, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 622, last 614, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 630, last 614, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Health state current 636, last 614, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 646, last 614, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Health state current 652, last 646, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
Dec 19 12:15:13 SC-1 osafimmnd[6451]: Ccb 574 COMMITTED (TraceC)
Dec 19 12:15:13 PL-3 osafimmnd[4905]: Ccb 574 COMMITTED (TraceC)
Dec 19 12:15:13 SC-2 osafimmnd[5121]: Ccb 574 COMMITTED (TraceC)
Dec 19 12:15:13 PL-4 osafimmnd[4935]: Ccb 574 COMMITTED (TraceC)
7281 12:15:13 12/19/2012 IN TraceC "DBG: Terminating relayD for session TestProf_1
7282 12:15:13 12/19/2012 NO TraceC "Deactivate complete for session "TestProf_1"
7283 12:15:13 12/19/2012 IN TraceC "DBG: deactivateSessionOnTracePsComplete calling TraceCHousekeeping::handleDelayedSessionWipes() for session traceSessionRecordingId=TestProf_1,traceMId=1
7284 12:15:13 12/19/2012 IN TraceC "DBG: !!! CcMasterQueueRunner took 40067506us to operate !!!
7285 12:15:13 12/19/2012 IN TraceC "DBG: !!! Jobs took excessively long to complete: 40067574us !!!
7286 12:15:13 12/19/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
7287 12:15:13 12/19/2012 IN TraceC "DBG: Received death of pid 9082 with ret 9.
7288 12:15:13 12/19/2012 IN TraceC "DBG: No handler for pid 9082.
7289 12:15:13 12/19/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProf,traceMId=1". Saf ErrorCode: SA_AIS_OK
Wed Dec 19 12:15:13 EST 2012
Printing Profile
####################
Wed Dec 19 12:15:13 EST 2012
consistentLogs : NOT_ENFORCED
description : ""
latestSessionId : 1
logLevelDefault : TRACE_DEBUG_SYSTEM(7)
state : INACTIVE
traceExpressions : com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA,TRACE_DEBUG_MODULE(10)
--------------------------------
progress.actionName : deactivateSession
progress.additionalInfo : ""
progress.info : Trace deactivation is complete
progress.percentage : 100
progress.result : SUCCESS
progress.resultInfo : Trace deactivateSession was completed successfully
progress.state : FINISHED
progress.timeActionCompleted : 12/19/12T12:15:13-0500
progress.timeActionStarted : 12/19/12T12:14:32-0500
progress.timeOfLastStatusUpdate : 12/19/12T12:15:13-0500
Wed Dec 19 12:15:13 EST 2012
Printing Session
####################
Wed Dec 19 12:15:13 EST 2012
errors : NoError;
logLevelDefault : TRACE_DEBUG_SYSTEM(7)
startTime : 12/19/12T12:14:21-0500
state : COMPLETE
stopTime : 12/19/12T12:15:13-0500
traceExpressions : com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA,TRACE_DEBUG_MODULE(10)
traceProfileId : TestProf
--------------------------------
progress : ""
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Fork1-8527-20121219-121423
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Fork1-8517-20121219-121423
20K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Thread1-8518-20121219-121423
20K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_type1-8516-20121219-121423
92K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust
96K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1
28K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_type1-19676-20121219-121421
12K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Thread1-19678-20121219-121421
16K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Fork1-19677-20121219-121421
16K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Fork1-19685-20121219-121421
76K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust
80K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Fork1-19568-20121219-121421
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Fork1-19578-20121219-121421
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Thread1-19569-20121219-121421
28K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_type1-19567-20121219-121421
104K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust
108K /storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3
20K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_type1-22524-20121219-121421
12K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Fork1-22525-20121219-121421
8.0K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Thread1-22526-20121219-121421
24K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Fork1-22535-20121219-121421
68K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust
72K /storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2
364K /storage/no-backup/tracecc-apr9010500/TestProf_1
Wed Dec 19 12:15:13 EST 2012
Printing Ports after Session has been deactivated
####################
Wed Dec 19 12:15:13 EST 2012
Converting Session
####################
Wed Dec 19 12:15:13 EST 2012
7290 12:15:13 12/19/2012 IN TraceC "DBG: Converting output operation
7291 12:15:13 12/19/2012 IN TraceC "DBG: Try to async-remove directory "/storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs"
7292 12:15:13 12/19/2012 IN TraceC "DBG: Directory /storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs was created successfully!
7293 12:15:13 12/19/2012 NO TraceC "Converting session "TestProf_1"
7294 12:15:13 12/19/2012 IN TraceC "DBG: resetOrCreate traceSessionRecordingId=TestProf_1,traceMId=1
7295 12:15:13 12/19/2012 IN TraceC "DBG: ConvertAsyncProgress: Create request for child object of traceSessionRecordingId=TestProf_1,traceMId=1
7296 12:15:13 12/19/2012 IN TraceC "DBG: ConvertAsyncProgressImplementer: id=1,traceSessionRecordingId=TestProf_1,traceMId=1 was successfully created
7297 12:15:13 12/19/2012 IN TraceC "DBG: Return for invocation 1 value: 1, return code: 1 , SA_AIS_OK
7298 12:15:13 12/19/2012 IN TraceC "DBG: -== start convert output from /storage/no-backup/tracecc-apr9010500//TestProf_1/PL-3 to /storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_PL-3.log ==-
7299 12:15:13 12/19/2012 IN TraceC "DBG: === ConvertOutputTask::babelTraceConvert, bfile=/storage/no-backup/tracecc-apr9010500//TestProf_1/PL-3,desFile=/storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_PL-3.log ===
7300 12:15:13 12/19/2012 IN TraceC "DBG: processMostQueuedEvents : directory Converted_logs is being added to parent directory /storage/no-backup/tracecc-apr9010500/TestProf_1
7301 12:15:13 12/19/2012 IN TraceC "DBG: Dispatch: epoll_wait returned an error: 4
7302 12:15:13 12/19/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
7303 12:15:13 12/19/2012 IN TraceC "DBG: Received death of pid 9235 with ret 0.
7304 12:15:13 12/19/2012 IN TraceC "DBG: ConvertOutputTask::handleSigChild line=61 return: 0
7305 12:15:13 12/19/2012 IN TraceC "DBG: receiveConvertOutputResult() result: 0
7306 12:15:13 12/19/2012 IN TraceC "DBG: -== start convert output from /storage/no-backup/tracecc-apr9010500//TestProf_1/PL-4 to /storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_PL-4.log ==-
7307 12:15:13 12/19/2012 IN TraceC "DBG: === ConvertOutputTask::babelTraceConvert, bfile=/storage/no-backup/tracecc-apr9010500//TestProf_1/PL-4,desFile=/storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_PL-4.log ===
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 662, last 646, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
7308 12:15:17 12/19/2012 IN TraceC "DBG: Dispatch: epoll_wait returned an error: 4
7309 12:15:17 12/19/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
7310 12:15:17 12/19/2012 IN TraceC "DBG: Received death of pid 9237 with ret 256.
7311 12:15:17 12/19/2012 IN TraceC "DBG: ConvertOutputTask::handleSigChild line=61 return: 1
7312 12:15:17 12/19/2012 IN TraceC "DBG: receiveConvertOutputResult() result: 1
7313 12:15:17 12/19/2012 ER TraceC "Convert Session: TestProf_1 session log conversion failed
7314 12:15:17 12/19/2012 IN TraceC "DBG: -== start convert output from /storage/no-backup/tracecc-apr9010500//TestProf_1/SC-1 to /storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_SC-1.log ==-
7315 12:15:17 12/19/2012 IN TraceC "DBG: === ConvertOutputTask::babelTraceConvert, bfile=/storage/no-backup/tracecc-apr9010500//TestProf_1/SC-1,desFile=/storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_SC-1.log ===
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 671, last 646, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
7316 12:15:20 12/19/2012 IN TraceC "DBG: Dispatch: epoll_wait returned an error: 4
7317 12:15:20 12/19/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
7318 12:15:20 12/19/2012 IN TraceC "DBG: Received death of pid 9245 with ret 256.
7319 12:15:20 12/19/2012 IN TraceC "DBG: ConvertOutputTask::handleSigChild line=61 return: 1
7320 12:15:20 12/19/2012 IN TraceC "DBG: receiveConvertOutputResult() result: 1
7321 12:15:20 12/19/2012 ER TraceC "Convert Session: TestProf_1 session log conversion failed
7322 12:15:20 12/19/2012 IN TraceC "DBG: -== start convert output from /storage/no-backup/tracecc-apr9010500//TestProf_1/SC-2 to /storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_SC-2.log ==-
7323 12:15:20 12/19/2012 IN TraceC "DBG: === ConvertOutputTask::babelTraceConvert, bfile=/storage/no-backup/tracecc-apr9010500//TestProf_1/SC-2,desFile=/storage/no-backup/tracecc-apr9010500//TestProf_1/Converted_logs/Node_SC-2.log ===
7324 12:15:23 12/19/2012 IN TraceC "DBG: Dispatch: epoll_wait returned an error: 4
7325 12:15:23 12/19/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
7326 12:15:23 12/19/2012 IN TraceC "DBG: Received death of pid 9249 with ret 256.
7327 12:15:23 12/19/2012 IN TraceC "DBG: ConvertOutputTask::handleSigChild line=61 return: 1
7328 12:15:23 12/19/2012 IN TraceC "DBG: receiveConvertOutputResult() result: 1
7329 12:15:23 12/19/2012 ER TraceC "Convert Session: TestProf_1 session log conversion failed
7330 12:15:23 12/19/2012 NO TraceC "Completed conversion of session "TestProf_1".
Wed Dec 19 12:15:23 EST 2012
Listing Session Directory Structure
####################
/storage/no-backup/tracecc-apr9010500/TestProf_1:
total 32
drwxr-xr-x 7 root root 4096 Dec 19 12:15 .
drwxr-xr-x 5 root root 4096 Dec 19 12:14 ..
drwxr-xr-x 2 root root 4096 Dec 19 12:15 Converted_logs
drwxr-x--- 3 root root 4096 Dec 19 12:14 PL-3
drwxr-x--- 3 root root 4096 Dec 19 12:14 PL-4
drwxr-x--- 3 root root 4096 Dec 19 12:14 SC-1
drwxr-x--- 3 root root 4096 Dec 19 12:14 SC-2
-rw-r--r-- 1 root root 230 Dec 19 12:15 session_metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/Converted_logs:
total 72
drwxr-xr-x 2 root root 4096 Dec 19 12:15 .
drwxr-xr-x 7 root root 4096 Dec 19 12:15 ..
-rwxr-xr-x 1 root root 26215 Dec 19 12:15 Node_PL-3.log
-rwxr-xr-x 1 root root 26705 Dec 19 12:15 Node_PL-4.log
-rwxr-xr-x 1 root root 0 Dec 19 12:15 Node_SC-1.log
-rwxr-xr-x 1 root root 0 Dec 19 12:15 Node_SC-2.log
-rw-r--r-- 1 root root 4284 Dec 19 12:15 conversionResult.log

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3:
total 12
drwxr-x--- 3 root root 4096 Dec 19 12:14 .
drwxr-xr-x 7 root root 4096 Dec 19 12:15 ..
drwxr-x--- 6 root root 4096 Dec 19 12:14 ust

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust:
total 24
drwxr-x--- 6 root root 4096 Dec 19 12:14 .
drwxr-x--- 3 root root 4096 Dec 19 12:14 ..
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-19568-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-19578-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Thread1-19569-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_type1-19567-20121219-121421

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Fork1-19568-20121219-121421:
total 28
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Fork1-19578-20121219-121421:
total 28
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_Thread1-19569-20121219-121421:
total 28
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-3/ust/TestApp_type1-19567-20121219-121421:
total 32
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 8192 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4:
total 12
drwxr-x--- 3 root root 4096 Dec 19 12:14 .
drwxr-xr-x 7 root root 4096 Dec 19 12:15 ..
drwxr-x--- 6 root root 4096 Dec 19 12:14 ust

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust:
total 24
drwxr-x--- 6 root root 4096 Dec 19 12:14 .
drwxr-x--- 3 root root 4096 Dec 19 12:14 ..
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-19677-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-19685-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Thread1-19678-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_type1-19676-20121219-121421

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Fork1-19677-20121219-121421:
total 20
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Fork1-19685-20121219-121421:
total 20
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_Thread1-19678-20121219-121421:
total 16
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/PL-4/ust/TestApp_type1-19676-20121219-121421:
total 32
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 8192 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1:
total 12
drwxr-x--- 3 root root 4096 Dec 19 12:14 .
drwxr-xr-x 7 root root 4096 Dec 19 12:15 ..
drwxr-x--- 6 root root 4096 Dec 19 12:14 ust

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust:
total 24
drwxr-x--- 6 root root 4096 Dec 19 12:14 .
drwxr-x--- 3 root root 4096 Dec 19 12:14 ..
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-8517-20121219-121423
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-8527-20121219-121423
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Thread1-8518-20121219-121423
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_type1-8516-20121219-121423

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Fork1-8517-20121219-121423:
total 28
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Fork1-8527-20121219-121423:
total 28
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_Thread1-8518-20121219-121423:
total 24
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-1/ust/TestApp_type1-8516-20121219-121423:
total 24
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 8192 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2:
total 12
drwxr-x--- 3 root root 4096 Dec 19 12:14 .
drwxr-xr-x 7 root root 4096 Dec 19 12:15 ..
drwxr-x--- 6 root root 4096 Dec 19 12:14 ust

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust:
total 24
drwxr-x--- 6 root root 4096 Dec 19 12:14 .
drwxr-x--- 3 root root 4096 Dec 19 12:14 ..
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-22525-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Fork1-22535-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_Thread1-22526-20121219-121421
drwxr-x--- 2 root root 4096 Dec 19 12:14 TestApp_type1-22524-20121219-121421

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Fork1-22525-20121219-121421:
total 16
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Fork1-22535-20121219-121421:
total 28
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_Thread1-22526-20121219-121421:
total 12
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata

/storage/no-backup/tracecc-apr9010500/TestProf_1/SC-2/ust/TestApp_type1-22524-20121219-121421:
total 24
drwxr-x--- 2 root root 4096 Dec 19 12:14 .
drwxr-x--- 6 root root 4096 Dec 19 12:14 ..
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_0
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 channel0_1
-rwxr-xr-x 1 root root 0 Dec 19 12:14 channel0_2
-rwxr-xr-x 1 root root 8192 Dec 19 12:14 channel0_3
-rwxr-xr-x 1 root root 4096 Dec 19 12:14 metadata
Wed Dec 19 12:15:23 EST 2012
Printing Session
####################
Wed Dec 19 12:15:23 EST 2012
errors : NoError;
logLevelDefault : TRACE_DEBUG_SYSTEM(7)
startTime : 12/19/12T12:14:21-0500
state : COMPLETE
stopTime : 12/19/12T12:15:13-0500
traceExpressions : com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA,TRACE_DEBUG_MODULE(10)
traceProfileId : TestProf
--------------------------------
progress.actionName : convertOutput
progress.additionalInfo : nodeName=All processId=All
progress.info : Convert is terminated with failure!
progress.percentage : 100
progress.result : FAILURE
progress.resultInfo : Failed to convert output
progress.state : FINISHED
progress.timeActionCompleted : 12/19/12T12:15:23-0500
progress.timeActionStarted : 12/19/12T12:15:13-0500
progress.timeOfLastStatusUpdate : ""
Wed Dec 19 12:15:23 EST 2012
Deleting Session
####################
Wed Dec 19 12:15:23 EST 2012
Deleting Profile
####################
Wed Dec 19 12:15:24 EST 2012
Dec 19 12:15:24 SC-1 osafimmnd[6451]: Ccb 579 COMMITTED (TraceCLI)
###########################################################################
###########################################################################
###########################################################################
SC-1:/storage/no-backup/coremw/var/log/saflog # Dec 19 12:15:24 PL-4 osafimmnd[4935]: Ccb 579 COMMITTED (TraceCLI)
Dec 19 12:15:24 PL-3 osafimmnd[4905]: Ccb 579 COMMITTED (TraceCLI)
Dec 19 12:15:24 SC-2 osafimmnd[5121]: Ccb 579 COMMITTED (TraceCLI)
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 678, last 646, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Health state current 684, last 678, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3233]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3278]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3282]
DEBUG1: Health state current 694, last 678, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:476]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3191]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 53, last 53, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 33, last 33, ret 0 [in health_check_state() at health.c:127]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
DEBUG1: Receiving data from client for health... [in thread_manage_health() at main.c:3041]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 1, last 1, ret 0 [in health_check_state() at health.c:127]
DEBUG1: Health state current 15, last 15, ret 0 [in health_check_state() at health.c:127]
DEBUG3: Health consumer check 1 [in check_consumer_health() at main.c:1941]
DEBUG2: Health check return value 0 [in thread_manage_health() at main.c:3094]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2992]
(4-4/5)