Project

General

Profile

Bug #400 » sessiond_dies_colliding_domain_and_event.txt

Log - Jesus Garcia, 11/15/2012 06:18 PM

 
SC-1:/storage/no-backup/coremw/var/log/saflog # date;ps -eaf | egrep "trace|lttng" | grep -v grep
Thu Nov 15 15:47:13 EST 2012
root 1758 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_c
root 1770 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_p
root 10655 1 0 15:23 ? 00:00:00 lttng-sessiond -d
root 31829 1 0 12:49 ? 00:00:02 /opt/trace_ea/bin/TraceEa
root 31842 31829 0 12:49 ? 00:00:00 /opt/trace_ea/bin/TraceEa
SC-1:/storage/no-backup/coremw/var/log/saflog # pkill -9 lttng-sessiond; usleep 100000; lttng-sessiond -vvv --verbose-consumer --no-kernel > /cluster/temp/eusgarc/sc1_sessiond.log 2>&1 &
[7] 13154
SC-1:/storage/no-backup/coremw/var/log/saflog # sleep 2
DEBUG3: Creating LTTng run directory: /var/run/lttng [in create_lttng_rundir() at main.c:3662]
DEBUG2: Kernel consumer err path: /var/run/lttng/kconsumerd/error [in main() at main.c:3910]
DEBUG2: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command [in main() at main.c:3912]
DEBUG1: Client socket path /var/run/lttng/client-lttng-sessiond [in main() at main.c:3965]
DEBUG1: Application socket path /var/run/lttng/apps-lttng-sessiond [in main() at main.c:3966]
DEBUG1: LTTng run directory path: /var/run/lttng [in main() at main.c:3967]
DEBUG2: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error [in main() at main.c:3976]
DEBUG2: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command [in main() at main.c:3978]
DEBUG2: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error [in main() at main.c:3987]
DEBUG2: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command [in main() at main.c:3989]
DEBUG3: Created hashtable size 4 at 0x6420a0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x6425c0 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:3704]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd64 [in set_consumer_sockets() at main.c:3704]
DEBUG2: Creating consumer directory: /var/run/lttng/ustconsumerd32 [in set_consumer_sockets() at main.c:3704]
DEBUG1: Signal handler set for SIGTERM, SIGPIPE and SIGINT [in set_signal_handler() at main.c:3796]
DEBUG3: Session daemon client socket 8 and application socket 9 created [in init_daemon_socket() at main.c:3566]
Warning: No tracing group detected
DEBUG1: epoll set max size is 403353 [in compat_epoll_set_max_size() at compat-epoll.c:224]
DEBUG1: Command subsystem initialized [in cmd_init() at cmd.c:2460]
DEBUG1: [thread] Manage health check started [in thread_manage_health() at main.c:2928]
DEBUG1: Health check ready [in thread_manage_health() at main.c:2967]
DEBUG1: [thread] Manage client started [in thread_manage_clients() at main.c:3122]
DEBUG1: [thread] Dispatch UST command started [in thread_dispatch_ust_registration() at main.c:1284]
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:1294]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: [thread] Manage application registration started [in thread_registration_apps() at main.c:1360]
DEBUG1: Notifying applications of session daemon state: 1 [in notify_ust_apps() at main.c:497]
DEBUG1: [thread] Manage application started [in thread_manage_apps() at main.c:1095]
DEBUG1: Apps thread polling on 2 fds [in thread_manage_apps() at main.c:1124]
DEBUG1: Got the wait shm fd 17 [in get_wait_shm() at shm.c:117]
DEBUG1: Futex wait update active 1 [in futex_wait_update() at futex.c:63]
DEBUG1: Accepting application registration [in thread_registration_apps() at main.c:1393]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Nothing recv() from client... continuing [in thread_manage_clients() at main.c:3253]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2181]
DEBUG1: Waiting for 1 URIs from client ... [in process_client_msg() at main.c:2689]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session _Trace_EA created in (null) with ID 0 by UID 0 GID 0 [in session_create() at session.c:236]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x64db90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting trace directory path from URI to /dev/null/ [in add_uri_to_consumer() at cmd.c:407]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session _Trace_EA by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name _Trace_EA [in session_find_by_name() at session.c:122]
DEBUG3: No kernel session when tearing down session [in kernel_destroy_session() at kernel.c:730]
DEBUG1: Destroying session _Trace_EA [in session_destroy() at session.c:149]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
SC-1:/storage/no-backup/coremw/var/log/saflog # /cluster/temp/eusgarc/test_once
Thu Nov 15 15:47:15 EST 2012
root 1758 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_c
root 1770 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_p
root 13154 13741 0 15:47 pts/1 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 31829 1 0 12:49 ? 00:00:02 /opt/trace_ea/bin/TraceEa
root 31842 31829 0 12:49 ? 00:00:00 /opt/trace_ea/bin/TraceEa
Thu Nov 15 15:47:15 EST 2012
Creating Profile
####################
Thu Nov 15 15:47:15 EST 2012
Nov 15 15:47:15 SC-1 osafimmnd[6429]: Ccb 7874 COMMITTED (TraceCLI)
Nov 15 15:47:15 PL-3 osafimmnd[4931]: Ccb 7874 COMMITTED (TraceCLI)
Nov 15 15:47:15 PL-4 osafimmnd[4947]: Ccb 7874 COMMITTED (TraceCLI)
Nov 15 15:47:15 SC-2 osafimmnd[5144]: Ccb 7874 COMMITTED (TraceCLI)
Thu Nov 15 15:47:15 EST 2012
Wait 1 sec...
Nov 15 15:47:15 SC-1 osafimmnd[6429]: Ccb 7875 COMMITTED (TraceC)
Nov 15 15:47:15 PL-3 osafimmnd[4931]: Ccb 7875 COMMITTED (TraceC)
Nov 15 15:47:15 PL-4 osafimmnd[4947]: Ccb 7875 COMMITTED (TraceC)
Nov 15 15:47:15 SC-2 osafimmnd[5144]: Ccb 7875 COMMITTED (TraceC)
30761 15:47:15 11/15/2012 IN TraceC "DBG: ProfileAdmin::profileIdValidator was called
30762 15:47:15 11/15/2012 IN TraceC "DBG: newvalue size=26
30763 15:47:15 11/15/2012 IN TraceC "DBG: newvalue=traceProfileId=TestProfile

30764 15:47:15 11/15/2012 IN TraceC "DBG: ProfileAdmin::traceExpressionsValidator was called
30765 15:47:15 11/15/2012 IN TraceC "DBG: traceExpressions size=2
30766 15:47:15 11/15/2012 IN TraceC "DBG: About to create a temporary session /_TraceCValidator_uwCq6r in path /tmp/_TraceCValidator_uwCq6r
30767 15:47:15 11/15/2012 IN TraceC "DBG: Try to remove directory "/tmp/_TraceCValidator_uwCq6r"
30768 15:47:15 11/15/2012 IN TraceC "DBG: Remove Directory "/tmp/_TraceCValidator_uwCq6r" Deleted!
30769 15:47:15 11/15/2012 IN TraceC "DBG: Create: class: AsyncActionProgress, parentName: traceProfileId=TestProfile,traceMId=1
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2181]
DEBUG1: Waiting for 1 URIs from client ... [in process_client_msg() at main.c:2689]
DEBUG2: Trying to find session by name /_TraceCValidator_uwCq6r [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session /_TraceCValidator_uwCq6r 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 /_TraceCValidator_uwCq6r [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x64db90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Setting trace directory path from URI to /tmp/_TraceCValidator_uwCq6r [in add_uri_to_consumer() at cmd.c:407]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session /_TraceCValidator_uwCq6r by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name /_TraceCValidator_uwCq6r [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2068]
DEBUG3: Created hashtable size 4 at 0x6469d0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x646f10 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x647450 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x653110 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:143]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2020]
DEBUG3: Created hashtable size 4 at 0x653110 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Copy session consumer subdir /ust [in copy_session_consumer() at main.c:2038]
DEBUG1: Spawning consumerd [in spawn_consumerd() at main.c:1701]
DEBUG2: Consumer pid 13173 [in start_consumerd() at main.c:1882]
DEBUG2: Spawning consumer control thread [in start_consumerd() at main.c:1885]
DEBUG1: [thread] Manage consumer started [in thread_manage_consumer() at main.c:845]
DEBUG1: Using 64-bit UST consumer at: /usr/lib64/lttng/libexec/lttng-consumerd [in spawn_consumerd() at main.c:1775]
DEBUG1: epoll set max size is 403353 [in compat_epoll_set_max_size() at compat-epoll.c:224]
DEBUG3: Created hashtable size 4 at 0x61f030 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x61f570 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x61fab0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x61fff0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x620530 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: Connecting to error socket /var/run/lttng/ustconsumerd64/error [in main() at lttng-consumerd.c:358]
DEBUG3: Created hashtable size 4 at 0x620ec0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: Thread metadata poll started [in consumer_thread_metadata_poll() at consumer.c:2000]
DEBUG1: Updating poll fd array [in consumer_update_poll_array() at consumer.c:901]
DEBUG1: polling on 1 fd [in consumer_thread_data_poll() at consumer.c:2249]
DEBUG1: Creating command socket /var/run/lttng/ustconsumerd64/command [in consumer_thread_sessiond_poll() at consumer.c:2447]
DEBUG1: Metadata main loop started [in consumer_thread_metadata_poll() at consumer.c:2015]
DEBUG1: Metadata poll wait with 1 fd(s) [in consumer_thread_metadata_poll() at consumer.c:2028]
DEBUG1: Sending ready command to lttng-sessiond [in consumer_thread_sessiond_poll() at consumer.c:2460]
DEBUG1: Connection on client_socket [in consumer_thread_sessiond_poll() at consumeDEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG1: Enabling channel channel0 for session /_TraceCValidator_uwCq6r [in cmd_enable_channel() at cmd.c:822]
DEBUG2: Trace UST channel channel0 not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:52]
DEBUG3: Created hashtable size 4 at 0x654ac0 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x655000 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:207]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:273]
DEBUG2: UST app adding channel channel0 to global domain for session id 1 [in ust_app_create_channel_glb() at ust-app.c:1994]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:298]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 9 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session /_TraceCValidator_uwCq6r by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name /_TraceCValidator_uwCq6r [in session_find_by_name() at session.c:122]
DEBUG3: No kernel session when tearing down session [in kernel_destroy_session() at kernel.c:730]
DEBUG1: Destroy all UST traces [in ust_app_destroy_trace_all() at ust-app.c:2514]
DEBUG2: Trace UST destroy session 1 [in trace_ust_destroy_session() at trace-ust.c:576]
DEBUG1: Destroying session /_TraceCValidator_uwCq6r [in session_destroy() at session.c:149]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG2: Trace destroy UST channel channel0 [in trace_ust_destroy_channel() at trace-ust.c:459]
Thu Nov 15 15:47:16 EST 2012
root 1758 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_c
root 1770 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_p
root 13154 13741 0 15:47 pts/1 00:00:00 lttng-sessiond -vvv --verbose-consumer --no-kernel
root 13173 13154 0 15:47 pts/1 00:00:00 lttng-consumerd --verbose -u --consumerd-cmd-sock /var/run/lttng/ustconsumerd64/command --consumerd-err-sock /var/run/lttng/ustconsumerd64/error
root 31829 1 0 12:49 ? 00:00:02 /opt/trace_ea/bin/TraceEa
root 31842 31829 0 12:49 ? 00:00:00 /opt/trace_ea/bin/TraceEa
Thu Nov 15 15:47:16 EST 2012
Activating Profile
####################
Thu Nov 15 15:47:16 EST 2012
30770 15:47:16 11/15/2012 IN TraceC "DBG: Activating
30771 15:47:16 11/15/2012 IN TraceC "DBG: creating session traceSessionRecordingId=TestProfile_1,traceMId=1 as a runtime object
30772 15:47:16 11/15/2012 NO TraceC "Activating Session TestProfile_1.
30773 15:47:16 11/15/2012 IN TraceC "DBG: Directory /home/trace//TestProfile_1 was created successfully!
30774 15:47:16 11/15/2012 IN TraceC "DBG: Return for invocation 1 value: 1, return code: 1 , SA_AIS_OK
30775 15:47:16 11/15/2012 IN TraceC "DBG: relayD ip address is found: 192.168.0.1
30776 15:47:16 11/15/2012 IN TraceC "DBG: RelayDManager::start() Control port selected: 55211
30777 15:47:16 11/15/2012 IN TraceC "DBG: RelayDManager::start() Data port selected: 55368
30778 15:47:16 11/15/2012 IN TraceC "DBG: RelayDManager::start() Pipe opened
30779 15:47:16 11/15/2012 IN TraceC "DBG: relayD ip address is found: 192.168.0.1
30780 15:47:16 11/15/2012 IN TraceC "DBG: RelayDManager::start() RelayD for "TestProfile_1" pid: 13190 bound on 192.168.0.1:55211:55368
30781 15:47:16 11/15/2012 IN TraceC "DBG: Done Activating
30782 15:47:16 11/15/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestProfile_1 is being added to parent directory /home/trace
Nov 15 15:47:16 SC-1 osafimmnd[6429]: Ccb 7877 COMMITTED (TraceC)
Nov 15 15:47:16 PL-3 osafimmnd[4931]: Ccb 7877 COMMITTED (TraceC)
Nov 15 15:47:16 PL-4 osafimmnd[4947]: Ccb 7877 COMMITTED (TraceC)
Nov 15 15:47:16 SC-2 osafimmnd[5144]: Ccb 7877 COMMITTED (TraceC)
Nov 15 15:47:16 SC-1 osafimmnd[6429]: Ccb 7878 COMMITTED (TraceC)
Nov 15 15:47:16 PL-3 osafimmnd[4931]: Ccb 7878 COMMITTED (TraceC)
Nov 15 15:47:16 SC-2 osafimmnd[5144]: Ccb 7878 COMMITTED (TraceC)
Nov 15 15:47:17 PL-4 osafimmnd[4947]: Ccb 7878 COMMITTED (TraceC)
30783 15:47:16 11/15/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProfile,traceMId=1". Saf ErrorCode: SA_AIS_OK
30784 15:47:17 11/15/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProfile,traceMId=1". Saf ErrorCode: SA_AIS_OK
DEBUG1: UST registration received with pid:12547 ppid:1 uid:0 gid:0 sock:17 name:TestApp_Fork1 (version 2.0) [in thread_registration_apps() at main.c:1493]
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:1393]
DEBUG1: UST registration received with pid:12550 ppid:12547 uid:0 gid:0 sock:21 name:TestApp_Fork1 (version 2.0) [in thread_registration_apps() at main.c:1493]
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:1393]
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:12491 ppid:1 uid:0 gid:0 sock:22 name:TestApp_type1 (version 2.0) [in thread_registration_apps() at main.c:1493]
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:1393]
DEBUG1: Dispatching UST registration pid:12547 ppid:1 uid:0 gid:0 sock:17 name:TestApp_Fork1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1306]
DEBUG1: UST registration received with pid:12604 ppid:1 uid:0 gid:0 sock:23 name:TestApp_Thread1 (version 2.0) [in thread_registration_apps() at main.c:1493]
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:1393]
DEBUG1: Dispatching UST registration pid:12550 ppid:12547 uid:0 gid:0 sock:21 name:TestApp_Fork1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1306]
DEBUG1: Dispatching UST registration pid:12491 ppid:1 uid:0 gid:0 sock:22 name:TestApp_type1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1306]
DEBUG1: Dispatching UST registration pid:12604 ppid:1 uid:0 gid:0 sock:23 name:TestApp_Thread1 (version 2.0) [in thread_dispatch_ust_registration() at main.c:1306]
DEBUG1: Woken up but nothing in the UST command queue [in thread_dispatch_ust_registration() at main.c:1294]
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:1294]
DEBUG3: Created hashtable size 4 at 0x646b40 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:12547 ppid:1 uid:0 gid:0 sock:17 name:TestApp_Fork1 (version 2.0) [in ust_app_register() at ust-app.c:1467]
DEBUG2: UST app PID 12547 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2945]
DEBUG1: Apps with sock 17 added to poll set [in thread_manage_apps() at main.c:1221]
DEBUG1: Apps thread polling on 3 fds [in thread_manage_apps() at main.c:1124]
DEBUG3: Created hashtable size 4 at 0x64db90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:12550 ppid:12547 uid:0 gid:0 sock:21 name:TestApp_Fork1 (version 2.0) [in ust_app_register() at ust-app.c:1467]
DEBUG2: UST app PID 12550 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2945]
DEBUG1: Apps with sock 21 added to poll set [in thread_manage_apps() at main.c:1221]
DEBUG1: Apps thread polling on 4 fds [in thread_manage_apps() at main.c:1124]
DEBUG3: Created hashtable size 4 at 0x654ac0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:12491 ppid:1 uid:0 gid:0 sock:22 name:TestApp_type1 (version 2.0) [in ust_app_register() at ust-app.c:1467]
DEBUG2: UST app PID 12491 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2945]
DEBUG1: Apps with sock 22 added to poll set [in thread_manage_apps() at main.c:1221]
DEBUG1: Apps thread polling on 5 fds [in thread_manage_apps() at main.c:1124]
DEBUG3: Created hashtable size 4 at 0x655000 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG1: App registered with pid:12604 ppid:1 uid:0 gid:0 sock:23 name:TestApp_Thread1 (version 2.0) [in ust_app_register() at ust-app.c:1467]
DEBUG2: UST app PID 12604 is compatible with internal major version 3 (supporting == 3) [in ust_app_validate_version() at ust-app.c:2945]
DEBUG1: Apps with sock 23 added to poll set [in thread_manage_apps() at main.c:1221]
DEBUG1: Apps thread polling on 6 fds [in thread_manage_apps() at main.c:1124]
30785 15:47:19 11/15/2012 IN TraceC "DBG: Performing activate after relayD wait for session TestProfile_1
30786 15:47:19 11/15/2012 IN TraceC "DBG: relayD ip address is found: 192.168.0.1
30787 15:47:19 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-3,traceMId=1, op: 2, addr: 0x7F235800B260
30788 15:47:19 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-4,traceMId=1, op: 2, addr: 0x7F235800AFC0
30789 15:47:19 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-1,traceMId=1, op: 2, addr: 0x7F235800B140
30790 15:47:19 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-2,traceMId=1, op: 2, addr: 0x7F2358008690
30791 15:47:19 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F235800B260
30792 15:47:19 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F235800AFC0
30793 15:47:19 11/15/2012 IN TraceP_PL-3 "Activating
30794 15:47:19 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F235800B140
30795 15:47:19 11/15/2012 IN TraceP_PL-4 "Activating
30796 15:47:19 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F2358008690
30797 15:47:19 11/15/2012 IN TraceP_SC-1 "Activating
30798 15:47:19 11/15/2012 IN TraceP_SC-2 "Activating
30799 15:47:19 11/15/2012 IN TraceP_SC-1 "DBG: LTTNG session activation requested, session name TestProfile_1 with url net://192.168.0.1:55211:55368/./
30800 15:47:19 11/15/2012 IN TraceP_SC-1 "DBG: LTTNG, enabling event, event name com_ericsson_cba_trace_testapp_lowtraf
30801 15:47:19 11/15/2012 IN TraceP_SC-1 "DBG: Dual event. enabling both com_ericsson_cba_trace_testapp_lowtraf:* and com_ericsson_cba_trace_testapp_lowtraf_*
30802 15:47:19 11/15/2012 IN TraceP_SC-1 "DBG: LTTNG, enabling event, event name com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 8 [in process_client_msg() at main.c:2181]
DEBUG1: Waiting for 2 URIs from client ... [in process_client_msg() at main.c:2689]
DEBUG2: Trying to find session by name TestProfile_1 [in session_find_by_name() at session.c:122]
DEBUG1: Tracing session TestProfile_1 created in (null) with ID 2 by UID 0 GID 0 [in session_create() at session.c:236]
DEBUG2: Trying to find session by name TestProfile_1 [in session_find_by_name() at session.c:122]
DEBUG3: Created hashtable size 4 at 0x647330 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 55211 [in consumer_set_network_uri() at consumer.c:382]
DEBUG3: Consumer set network uri subdir path SC-1/./ [in consumer_set_network_uri() at consumer.c:434]
DEBUG3: Append domain trace name to subdir SC-1/./ [in add_uri_to_consumer() at cmd.c:402]
DEBUG2: Setting network URI to consumer [in add_uri_to_consumer() at cmd.c:375]
DEBUG3: Consumer data URI set with port 55368 [in consumer_set_network_uri() at consumer.c:391]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 5 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session TestProfile_1 by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name TestProfile_1 [in session_find_by_name() at session.c:122]
DEBUG1: Creating UST session [in create_ust_session() at main.c:2068]
DEBUG3: Created hashtable size 4 at 0x64c9f0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64cf30 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x64d470 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x653110 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:143]
DEBUG3: Copying tracing session consumer output in UST session [in copy_session_consumer() at main.c:2020]
DEBUG3: Created hashtable size 4 at 0x653110 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:2038]
DEBUG3: Consumer socket created (fd: 20) and added to output [in consumer_create_socket() at consumer.c:141]
DEBUG1: Enabling channel channel0 for session TestProfile_1 [in cmd_enable_channel() at cmd.c:822]
DEBUG2: Trace UST channel channel0 not found by name [in trace_ust_find_channel_by_name() at trace-ust.c:52]
DEBUG3: Created hashtable size 4 at 0x656990 of type 0 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x656e40 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:207]
DEBUG2: Channel channel0 being created in UST global domain [in channel_ust_create() at channel.c:273]
DEBUG2: UST app adding channel channel0 to global domain for session id 2 [in ust_app_create_channel_glb() at ust-app.c:1994]
DEBUG2: UST app pid: 12604 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:961]
DEBUG3: Created hashtable size 4 at 0x658350 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:870]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:988]
DEBUG3: Created hashtable size 4 at 0x6595b0 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x659850 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:302]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:810]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:847]
DEBUG2: UST app channel channel0 created successfully for pid:12604 and sock:23 [in create_ust_channel() at ust-app.c:683]
DEBUG2: UST app create channel channel0 for PID 12604 completed [in create_ust_app_channel() at ust-app.c:1233]
DEBUG2: UST app pid: 12547 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:961]
DEBUG3: Created hashtable size 4 at 0x65ad60 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:870]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:988]
DEBUG3: Created hashtable size 4 at 0x65b530 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65ba70 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:302]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:810]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:847]
DEBUG2: UST app channel channel0 created successfully for pid:12547 and sock:17 [in create_ust_channel() at ust-app.c:683]
DEBUG2: UST app create channel channel0 for PID 12547 completed [in create_ust_app_channel() at ust-app.c:1233]
DEBUG2: UST app pid: 12491 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:961]
DEBUG3: Created hashtable size 4 at 0x65d150 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:870]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:988]
DEBUG3: Created hashtable size 4 at 0x65d940 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x65de80 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:302]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:810]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:847]
DEBUG2: UST app channel channel0 created successfully for pid:12491 and sock:22 [in create_ust_channel() at ust-app.c:683]
DEBUG2: UST app create channel channel0 for PID 12491 completed [in create_ust_app_channel() at ust-app.c:1233]
DEBUG2: UST app pid: 12550 session id 2 not found, creating it [in create_ust_app_session() at ust-app.c:961]
DEBUG3: Created hashtable size 4 at 0x65f560 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:870]
DEBUG2: UST app session created successfully with handle 1 [in create_ust_app_session() at ust-app.c:988]
DEBUG3: Created hashtable size 4 at 0x65fd50 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: Created hashtable size 4 at 0x660290 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:302]
DEBUG2: UST app shadow copy of channel channel0 started [in shadow_copy_channel() at ust-app.c:810]
DEBUG3: UST app shadow copy of channel channel0 done [in shadow_copy_channel() at ust-app.c:847]
DEBUG2: UST app channel channel0 created successfully for pid:12550 and sock:21 [in create_ust_channel() at ust-app.c:683]
DEBUG2: UST app create channel channel0 for PID 12550 completed [in create_ust_app_channel() at ust-app.c:1233]
DEBUG2: Channel channel0 created successfully [in channel_ust_create() at channel.c:298]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session TestProfile_1 by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name TestProfile_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:141]
DEBUG2: Trace UST channel channel0 found by name [in trace_ust_find_channel_by_name() at trace-ust.c:47]
DEBUG2: Trace UST event NOT found by name com_ericsson_cba_trace_testapp_lowtraf:* [in trace_ust_find_event_by_name() at trace-ust.c:79]
DEBUG3: Created hashtable size 4 at 0x660b90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST event com_ericsson_cba_trace_testapp_lowtraf:*, loglevel (1,14) created [in trace_ust_create_event() at trace-ust.c:286]
DEBUG1: UST app creating event com_ericsson_cba_trace_testapp_lowtraf:* for all apps for session id 2 [in ust_app_create_event_glb() at ust-app.c:2119]
DEBUG3: Created hashtable size 4 at 0x661460 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:* created successfully for pid:12604 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf:* for PID 12604 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x661e70 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:* created successfully for pid:12547 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf:* for PID 12547 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x662880 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:* created successfully for pid:12491 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf:* for PID 12491 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x663290 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:* created successfully for pid:12550 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf:* for PID 12550 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG1: Event UST com_ericsson_cba_trace_testapp_lowtraf:* created in channel channel0 [in event_ust_enable_tracepoint() at event.c:486]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session TestProfile_1 by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name TestProfile_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:141]
DEBUG2: Trace UST channel channel0 found by name [in trace_ust_find_channel_by_name() at trace-ust.c:47]
DEBUG2: Trace UST event NOT found by name com_ericsson_cba_trace_testapp_lowtraf_* [in trace_ust_find_event_by_name() at trace-ust.c:79]
DEBUG3: Created hashtable size 4 at 0x663b90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST event com_ericsson_cba_trace_testapp_lowtraf_*, loglevel (1,14) created [in trace_ust_create_event() at trace-ust.c:286]
DEBUG1: UST app creating event com_ericsson_cba_trace_testapp_lowtraf_* for all apps for session id 2 [in ust_app_create_event_glb() at ust-app.c:2119]
DEBUG3: Created hashtable size 4 at 0x664460 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf_* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf_* created successfully for pid:12604 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf_* for PID 12604 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x664e70 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf_* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf_* created successfully for pid:12547 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf_* for PID 12547 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x665880 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf_* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf_* created successfully for pid:12491 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf_* for PID 12491 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x666290 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf_* allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf_* created successfully for pid:12550 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf_* for PID 12550 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG1: Event UST com_ericsson_cba_trace_testapp_lowtraf_* created in channel channel0 [in event_ust_enable_tracepoint() at event.c:486]
DEBUG1: Sending response (size: 16, retcode: Success) [in thread_manage_clients() at main.c:3300]
DEBUG1: Clean command context structure [in clean_command_ctx() at main.c:477]
DEBUG1: Accepting client command ... [in thread_manage_clients() at main.c:3162]
DEBUG1: Wait for client response [in thread_manage_clients() at main.c:3204]
DEBUG1: Receiving data from client ... [in thread_manage_clients() at main.c:3249]
DEBUG1: Processing client command 6 [in process_client_msg() at main.c:2181]
DEBUG1: Getting session TestProfile_1 by name [in process_client_msg() at main.c:2252]
DEBUG2: Trying to find session by name TestProfile_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:141]
DEBUG2: Trace UST channel channel0 found by name [in trace_ust_find_channel_by_name() at trace-ust.c:47]
DEBUG2: Trace UST event NOT found by name com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA [in trace_ust_find_event_by_name() at trace-ust.c:79]
DEBUG3: Created hashtable size 4 at 0x666b90 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG2: Trace UST event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA, loglevel (1,14) created [in trace_ust_create_event() at trace-ust.c:286]
DEBUG1: UST app creating event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA for all apps for session id 2 [in ust_app_create_event_glb() at ust-app.c:2119]
DEBUG3: Created hashtable size 4 at 0x667460 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA created successfully for pid:12604 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA for PID 12604 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x667e70 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:337]
DEBUG2: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA created successfully for pid:12547 [in create_ust_event() at ust-app.c:723]
DEBUG2: UST app create event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA for PID 12547 completed [in create_ust_app_event() at ust-app.c:1284]
DEBUG3: Created hashtable size 4 at 0x668880 of type 1 [in lttng_ht_new() at hashtable.c:96]
DEBUG3: UST app event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA allocated [in alloc_ust_app_event() at ust-app.c:337]
Error: Error ustctl create event com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA for app pid: 12491 with ret -1026
lttng-sessiond: ust-app.c:1277: create_ust_app_event: Assertion `ret != -LTTNG_UST_ERR_EXIST' failed.
DEBUG1: Incoming command on sock [in consumer_thread_sessiond_poll() at consumer.c:2505]
DEBUG1: Consumer received unexpected message size 0 (expects 4416) [in lttng_ustconsumer_recv_cmd() at ust-consumer.c:109]
PERROR: sendmsg: Broken pipe [in lttcomm_send_unix_sock() at unix.c:204]
DEBUG1: Communication interrupted on command socket [in consumer_thread_sessiond_poll() at consumer.c:2516]
DEBUG1: consumer_thread_receive_fds exiting [in consumer_thread_sessiond_poll() at consumer.c:2526]
DEBUG1: poll num_rdy : 1 [in consumer_thread_data_poll() at consumer.c:2251]
DEBUG1: consumer_data_pipe wake up [in consumer_thread_data_poll() at consumer.c:2275]
DEBUG1: Consumer delete flagged data stream [in validate_endpoint_status_data_stream() at consumer.c:1938]
DEBUG1: polling thread exiting [in consumer_thread_data_poll() at consumer.c:2403]
DEBUG1: Metadata event catched in thread [in consumer_thread_metadata_poll() at consumer.c:2030]
DEBUG1: Metadata thread pipe hung up [in consumer_thread_metadata_poll() at consumer.c:2051]
DEBUG1: Metadata poll thread exiting [in consumer_thread_metadata_poll() at consumer.c:2160]
PERROR: sendmsg: Broken pipe [in lttcomm_send_unix_sock() at unix.c:204]
DEBUG1: Consumer destroying it. Closing everything. [in lttng_consumer_destroy() at consumer.c:1196]
Nov 15 15:47:20 SC-1 TraceEa: SessionD responsiveness test failed!
Nov 15 15:47:20 SC-1 TraceEa: sessiond faulted - Trying to Stop LTTNG
Nov 15 15:47:20 SC-2 TraceEa: SessionD responsiveness test failed!
Nov 15 15:47:20 SC-2 TraceEa: sessiond faulted - Trying to Stop LTTNG
Nov 15 15:47:20 SC-1 logger: lttng-sessiond is not running
Nov 15 15:47:20 SC-2 logger: lttng-sessiond is not running
Nov 15 15:47:20 SC-1 logger: lttng-consumerd is stopped
Nov 15 15:47:20 SC-1 osafimmnd[6429]: Ccb 7879 COMMITTED (TraceC)
Nov 15 15:47:20 PL-3 osafimmnd[4931]: Ccb 7879 COMMITTED (TraceC)
Nov 15 15:47:20 SC-2 osafimmnd[5144]: Ccb 7879 COMMITTED (TraceC)
Nov 15 15:47:20 PL-4 osafimmnd[4947]: Ccb 7879 COMMITTED (TraceC)
Nov 15 15:47:20 SC-1 osafimmnd[6429]: Ccb 7880 COMMITTED (TraceC)
Nov 15 15:47:20 PL-3 osafimmnd[4931]: Ccb 7880 COMMITTED (TraceC)
Nov 15 15:47:20 SC-2 osafimmnd[5144]: Ccb 7880 COMMITTED (TraceC)
Nov 15 15:47:20 PL-4 osafimmnd[4947]: Ccb 7880 COMMITTED (TraceC)
Nov 15 15:47:20 SC-1 osafimmnd[6429]: Ccb 7881 COMMITTED (TraceC)
Nov 15 15:47:20 PL-3 osafimmnd[4931]: Ccb 7881 COMMITTED (TraceC)
Nov 15 15:47:20 PL-4 osafimmnd[4947]: Ccb 7881 COMMITTED (TraceC)
Nov 15 15:47:20 SC-2 osafimmnd[5144]: Ccb 7881 COMMITTED (TraceC)
Nov 15 15:47:20 SC-1 osafimmnd[6429]: Ccb 7882 COMMITTED (TraceC)
Nov 15 15:47:20 PL-3 osafimmnd[4931]: Ccb 7882 COMMITTED (TraceC)
Nov 15 15:47:20 SC-2 osafimmnd[5144]: Ccb 7882 COMMITTED (TraceC)
Nov 15 15:47:20 PL-4 osafimmnd[4947]: Ccb 7882 COMMITTED (TraceC)
IMM ERROR: SA_AIS_ERR_FAILED_OPERATION
Thu Nov 15 15:47:20 EST 2012
Allow session to run for 3 sec...
Nov 15 15:47:21 PL-3 TraceEa: sessiond faulted - Trying to Stop LTTNG
Nov 15 15:47:21 PL-3 logger: lttng-sessiond is not running
30803 15:47:20 11/15/2012 ER TraceP_SC-1 "Error: Failed to start tracing for TestProfile_1, error: No session daemon is available
30804 15:47:20 11/15/2012 IN TraceP_SC-1 "DBG: Return for invocation -83 value: 20, return code: 1 , SA_AIS_OK
30805 15:47:20 11/15/2012 ER TraceP_SC-2 "Error: Failed to start tracing for TestProfile_1, error: No session daemon is available
30806 15:47:20 11/15/2012 ER TraceP_PL-3 "Error: Failed to start tracing for TestProfile_1, error: No session daemon is available
30807 15:47:20 11/15/2012 ER TraceP_PL-4 "Error: Failed to start tracing for TestProfile_1, error: No session daemon is available
30808 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
30809 15:47:20 11/15/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProfile,traceMId=1". Saf ErrorCode: SA_AIS_OK
30810 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
30811 15:47:20 11/15/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
30812 15:47:20 11/15/2012 ER TraceC "Error: TraceP "tracePId=SC-1,traceMId=1" could not activate Session "traceSessionRecordingId=TestProfile_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
30813 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
30814 15:47:20 11/15/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
30815 15:47:20 11/15/2012 ER TraceC "Error: TraceP "tracePId=SC-2,traceMId=1" could not activate Session "traceSessionRecordingId=TestProfile_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
30816 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 20 error: 1
30817 15:47:20 11/15/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
30818 15:47:20 11/15/2012 ER TraceC "Error: TraceP "tracePId=PL-3,traceMId=1" could not activate Session "traceSessionRecordingId=TestProfile_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
30819 15:47:20 11/15/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
30820 15:47:20 11/15/2012 IN TraceC "receiveTracePActivateResult() result: 1 op_result 20
30821 15:47:20 11/15/2012 ER TraceC "Error: TraceP "tracePId=PL-4,traceMId=1" could not activate Session "traceSessionRecordingId=TestProfile_1,traceMId=1". Saf Error:SA_AIS_OK . Operation Result:SA_AIS_ERR_BAD_OPERATION.
30822 15:47:20 11/15/2012 ER TraceC "No successful replies for session "traceSessionRecordingId=TestProfile_1,traceMId=1". Canceling.
30823 15:47:20 11/15/2012 IN TraceC "DBG: Requesting relay-d cancelation for session traceSessionRecordingId=TestProfile_1,traceMId=1
30824 15:47:20 11/15/2012 IN TraceC "DBG: Canceling relayD for session TestProfile_1
30825 15:47:20 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-3,traceMId=1, op: 4, addr: 0x7F2358008060
30826 15:47:20 11/15/2012 IN TraceC "DBG: Adding Cancel op 0x7F2358008060 for tracePId=PL-3,traceMId=1
30827 15:47:20 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=PL-4,traceMId=1, op: 4, addr: 0x7F23580083A0
30828 15:47:20 11/15/2012 IN TraceC "DBG: Adding Cancel op 0x7F23580083A0 for tracePId=PL-4,traceMId=1
30829 15:47:20 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-1,traceMId=1, op: 4, addr: 0x7F2358008150
30830 15:47:20 11/15/2012 IN TraceC "DBG: Adding Cancel op 0x7F2358008150 for tracePId=SC-1,traceMId=1
30831 15:47:20 11/15/2012 IN TraceC "DBG: Creating admin op: dn tracePId=SC-2,traceMId=1, op: 4, addr: 0x7F2358008260
30832 15:47:20 11/15/2012 IN TraceC "DBG: Adding Cancel op 0x7F2358008260 for tracePId=SC-2,traceMId=1
30833 15:47:20 11/15/2012 IN TraceC "DBG: Try to async-remove directory "/home/trace//TestProfile_1"
30834 15:47:20 11/15/2012 IN TraceC "DBG: remove called to delete file /home/trace//.tmp/TestProfile_1
30835 15:47:20 11/15/2012 IN TraceC "DBG: SigChildHandler: second half handling. death count: 1
30836 15:47:20 11/15/2012 IN TraceC "DBG: Received death of pid 13190 with ret 9.
30837 15:47:20 11/15/2012 IN TraceC "DBG: No handler for pid 13190.
30838 15:47:20 11/15/2012 IN TraceC "DBG: processMostQueuedEvents : directory TestProfile_1 has been deleted, moved, replaced or a delayed creation notification has been received in /home/trace
30839 15:47:20 11/15/2012 IN TraceC "DBG: TraceCHouseKeeping:directoryDeleteHandler is deleting TestProfile_1
30840 15:47:20 11/15/2012 IN TraceC "DBG: TraceCHouseKeeping: directoryDeleteHandler is deleting TestProfile_1
30841 15:47:20 11/15/2012 IN TraceC "DBG: directoryDeleteHandler : directory TestProfile_1 is being deleted
30842 15:47:20 11/15/2012 IN TraceC "DBG: Try to remove directory "/home/trace//.tmp/TestProfile_1"
30843 15:47:20 11/15/2012 IN TraceC "DBG: Remove Directory "/home/trace//.tmp/TestProfile_1" Deleted!
30844 15:47:20 11/15/2012 IN TraceC "DBG: Completed deletion of "/home/trace//.tmp/TestProfile_1"
30845 15:47:20 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F2358008060
30846 15:47:20 11/15/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProfile,traceMId=1". Saf ErrorCode: SA_AIS_OK
30847 15:47:20 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F23580083A0
30848 15:47:20 11/15/2012 IN TraceP_PL-3 "Cancelling
30849 15:47:20 11/15/2012 ER TraceP_PL-3 "Error: unable to list session from SessionD while checking for session. Error: -19
30850 15:47:20 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F2358008150
30851 15:47:20 11/15/2012 IN TraceP_PL-4 "Cancelling
30852 15:47:20 11/15/2012 ER TraceP_PL-4 "Error: unable to list session from SessionD while checking for session. Error: -19
30853 15:47:20 11/15/2012 IN TraceC "DBG: Invoking admin op 0x7F2358008260
30854 15:47:20 11/15/2012 IN TraceP_SC-1 "Cancelling
30855 15:47:20 11/15/2012 IN TraceP_SC-1 "DBG: TraceP Cancel: MO object traceSessionRecordingId=TestProfile_1,traceMId=1 not found in registry !
30856 15:47:20 11/15/2012 IN TraceP_SC-1 "DBG: Session count -19
30857 15:47:20 11/15/2012 ER TraceP_SC-1 "Error: unable to list session from SessionD while checking for session. Error: -19
30858 15:47:20 11/15/2012 IN TraceP_SC-1 "DBG: Return for invocation -87 value: 1, return code: 1 , SA_AIS_OK
30859 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
30860 15:47:20 11/15/2012 IN TraceP_SC-2 "Cancelling
30861 15:47:20 11/15/2012 ER TraceP_SC-2 "Error: unable to list session from SessionD while checking for session. Error: -19
30862 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
30863 15:47:20 11/15/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
30864 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
30865 15:47:20 11/15/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
30866 15:47:20 11/15/2012 IN TraceC "DBG: adminOperationInvokeAsyncCallback() operationReturnValue: 1 error: 1
30867 15:47:20 11/15/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
30868 15:47:20 11/15/2012 IN TraceC "DBG: saImmOmDispatch Succeeded
30869 15:47:20 11/15/2012 IN TraceC "receiveTracePCancelSessionResult() result: 1 op_result 1
30870 15:47:20 11/15/2012 IN TraceC "DBG: cancelSessionOnTracePsComplete deleting ConvertAsyncActionProgress if it exists traceSessionRecordingId=TestProfile_1,traceMId=1
30871 15:47:20 11/15/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProfile,traceMId=1". Saf ErrorCode: SA_AIS_OK
30872 15:47:20 11/15/2012 ER TraceC "Update AsyncActionProgress "id=1,traceProfileId=TestProfile,traceMId=1". Saf ErrorCode: SA_AIS_OK
Nov 15 15:47:21 SC-1 logger: lttng-sessiond is started
Nov 15 15:47:21 PL-4 logger: lttng-sessiond is started
Nov 15 15:47:22 PL-3 logger: lttng-sessiond is started
Nov 15 15:47:22 SC-2 logger: lttng-sessiond is started
Thu Nov 15 15:47:23 EST 2012
root 1758 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_c
root 1770 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_p
root 13211 1 0 15:47 ? 00:00:00 lttng-sessiond -d
root 31829 1 0 12:49 ? 00:00:02 /opt/trace_ea/bin/TraceEa
root 31842 31829 0 12:49 ? 00:00:00 /opt/trace_ea/bin/TraceEa
Thu Nov 15 15:47:23 EST 2012
Printing Session
####################
Thu Nov 15 15:47:23 EST 2012
ERROR: This recording, node name or process id does not exist
Try tracecc-recording-list to list available recordings
Thu Nov 15 15:47:23 EST 2012
Deactivating Profile
####################
Thu Nov 15 15:47:23 EST 2012
IMM ERROR: SA_AIS_ERR_NO_OP
Thu Nov 15 15:47:23 EST 2012
root 1758 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_c
root 1770 1 0 12:56 ? 00:00:00 /opt/trace/sbin/trace_p
root 13211 1 0 15:47 ? 00:00:00 lttng-sessiond -d
root 31829 1 0 12:49 ? 00:00:02 /opt/trace_ea/bin/TraceEa
root 31842 31829 0 12:49 ? 00:00:00 /opt/trace_ea/bin/TraceEa
Thu Nov 15 15:47:23 EST 2012
Printing Profile
####################
Thu Nov 15 15:47:23 EST 2012
consistentLogs : NOT_ENFORCED
description : ""
latestSessionId : 1
logLevelDefault : TRACE_DEBUG_SYSTEM(7)
state : INACTIVE
traceExpressions : com_ericsson_cba_trace_testapp_lowtraf,TRACE_DEBUG(14)
com_ericsson_cba_trace_testapp_lowtraf:TenPerSecA,TRACE_DEBUG(14)
--------------------------------
progress.actionName : cancelSession
progress.additionalInfo : Session Cancelled: No successful replies for session activation
progress.info : Trace cancellation is complete
progress.percentage : 100
progress.result : SUCCESS
progress.resultInfo : Trace cancelSession was completed successfully
progress.state : FINISHED
progress.timeActionCompleted : 11/15/12T15:47:20-0500
progress.timeActionStarted : 11/15/12T15:47:20-0500
progress.timeOfLastStatusUpdate : 11/15/12T15:47:20-0500
Thu Nov 15 15:47:23 EST 2012
Deleting Session
####################
Thu Nov 15 15:47:23 EST 2012
ERROR: This recording, node name or process id does not exist
Try tracecc-recording-list to list available recordings
Thu Nov 15 15:47:23 EST 2012
Deleting Profile
####################
Thu Nov 15 15:47:23 EST 2012
Nov 15 15:47:23 SC-1 osafimmnd[6429]: Ccb 7887 COMMITTED (TraceCLI)
Nov 15 15:47:23 SC-2 osafimmnd[5144]: Ccb 7887 COMMITTED (TraceCLI)
Nov 15 15:47:23 PL-3 osafimmnd[4931]: Ccb 7887 COMMITTED (TraceCLI)
Nov 15 15:47:23 PL-4 osafimmnd[4947]: Ccb 7887 COMMITTED (TraceCLI)
(1-1/4)