Actions
Bug #1144
openBabeltrace 1.5.3 intermittent error on lttng-live hooking
Status:
New
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
Start date:
12/15/2017
Due date:
% Done:
0%
Estimated time:
Description
[error] get_next_index failed [error] Stream 18446744073709551615 is not declared in metadata. [error] Open file mmap stream error. [error] [Context] Cannot open_mmap_trace of format ctf. [error] Error adding trace [warning] [Context] Cannot open_trace of format lttng-live at path net://localhost:50758/host/ci-node-standalone-amd64-02/trace. [warning] [Context] cannot open trace "net://localhost:50758/host/ci-node-standalone-amd64-02/trace" for reading. [error] opening trace "net://localhost:50758/host/ci-node-standalone-amd64-02/trace" for reading. [error] none of the specified trace paths could be opened.
Relayd output:
DEBUG3 - 12:54:40.648163 [31303/31303]: URI string: tcp://localhost:42335 (in uri_parse() at uri.c:324) DEBUG2 - 12:54:40.648401 [31303/31303]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165) DEBUG3 - 12:54:40.648409 [31303/31303]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 42335, data: 0 (in uri_parse() at uri.c:538) DEBUG3 - 12:54:40.648415 [31303/31303]: URI string: tcp://localhost:38120 (in uri_parse() at uri.c:324) DEBUG2 - 12:54:40.648436 [31303/31303]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165) DEBUG3 - 12:54:40.648439 [31303/31303]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 38120, data: 0 (in uri_parse() at uri.c:538) DEBUG3 - 12:54:40.648443 [31303/31303]: URI string: tcp://localhost:50758 (in uri_parse() at uri.c:324) DEBUG2 - 12:54:40.648458 [31303/31303]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165) DEBUG3 - 12:54:40.648461 [31303/31303]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 50758, data: 0 (in uri_parse() at uri.c:538) DEBUG1 - 12:54:40.648466 [31303/31303]: Signal handler set for SIGTERM, SIGUSR1, SIGPIPE and SIGINT (in set_signal_handler() at main.c:649) DEBUG1 - 12:54:40.648470 [31303/31303]: Health check time delta in seconds set to 20 (in health_init() at health.c:73) DEBUG1 - 12:54:40.648499 [31303/31303]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547) DEBUG3 - 12:54:40.648567 [31303/31303]: Created hashtable size 4 at 0x9faab0 of type 2 (in lttng_ht_new() at hashtable.c:145) DEBUG3 - 12:54:40.648577 [31303/31303]: Created hashtable size 4 at 0x9fae60 of type 2 (in lttng_ht_new() at hashtable.c:145) DEBUG3 - 12:54:40.648581 [31303/31303]: Created hashtable size 4 at 0x9fb230 of type 2 (in lttng_ht_new() at hashtable.c:145) DEBUG1 - 12:54:40.648640 [31303/31306]: [thread] Relay dispatcher started (in relay_thread_dispatcher() at main.c:962) DEBUG1 - 12:54:40.648747 [31303/31306]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77) DEBUG1 - 12:54:40.648755 [31303/31306]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:989) DEBUG1 - 12:54:40.648672 [31303/31305]: [thread] Manage health check started (in thread_manage_health() at health-relayd.c:239) DEBUG1 - 12:54:40.648814 [31303/31303]: epoll set max size is 821166 (in compat_epoll_set_max_size() at compat-epoll.c:296) DEBUG1 - 12:54:40.648706 [31303/31307]: [thread] Relay worker started (in relay_thread_worker() at main.c:2445) DEBUG3 - 12:54:40.648883 [31303/31307]: Created hashtable size 4 at 0x7fe1940008e0 of type 1 (in lttng_ht_new() at hashtable.c:145) DEBUG1 - 12:54:40.648804 [31303/31308]: [thread] Relay listener started (in relay_thread_listener() at main.c:771) DEBUG3 - 12:54:40.648894 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG3 - 12:54:40.649500 [31303/31305]: Creating LTTng run directory: /var/run/lttng (in create_lttng_rundir_with_perm() at health-relayd.c:94) DEBUG3 - 12:54:40.649528 [31303/31305]: Creating LTTng run directory: /var/run/lttng/relayd (in create_lttng_rundir_with_perm() at health-relayd.c:94) DEBUG1 - 12:54:40.649676 [31303/31309]: [thread] Live viewer relay dispatcher started (in thread_dispatcher() at live.c:647) DEBUG1 - 12:54:40.649690 [31303/31309]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77) DEBUG1 - 12:54:40.649696 [31303/31309]: Woken up but nothing in the live-viewer relay command queue (in thread_dispatcher() at live.c:675) DEBUG1 - 12:54:40.650092 [31303/31310]: [thread] Live viewer relay worker started (in thread_worker() at live.c:1932) DEBUG1 - 12:54:40.650186 [31303/31308]: Listening on sock 14 (in relay_socket_create() at main.c:739) DEBUG1 - 12:54:40.650222 [31303/31308]: Listening on sock 15 (in relay_socket_create() at main.c:739) DEBUG1 - 12:54:40.650238 [31303/31308]: Listener accepting connections (in relay_thread_listener() at main.c:817) DEBUG3 - 12:54:40.650623 [31303/31310]: Created hashtable size 4 at 0x7fe17c0008e0 of type 1 (in lttng_ht_new() at hashtable.c:145) DEBUG3 - 12:54:40.650641 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) Warning: No tracing group detected DEBUG1 - 12:54:40.650899 [31303/31305]: Health check ready (in thread_manage_health() at health-relayd.c:310) DEBUG1 - 12:54:40.650920 [31303/31311]: [thread] Relay live listener started (in thread_listener() at live.c:488) DEBUG1 - 12:54:40.650958 [31303/31311]: Listening on sock 18 for live (in init_socket() at live.c:455) DEBUG1 - 12:54:40.650975 [31303/31311]: Listener accepting live viewers connections (in thread_listener() at live.c:520) DEBUG1 - 12:54:41.802814 [31303/31308]: Relay new connection received (in relay_thread_listener() at main.c:835) DEBUG1 - 12:54:41.802850 [31303/31308]: Relay control connection accepted, socket 20 (in relay_thread_listener() at main.c:880) DEBUG1 - 12:54:41.802870 [31303/31308]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122) DEBUG1 - 12:54:41.802877 [31303/31308]: Listener accepting connections (in relay_thread_listener() at main.c:817) DEBUG1 - 12:54:41.802891 [31303/31306]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105) DEBUG1 - 12:54:41.802901 [31303/31306]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77) DEBUG1 - 12:54:41.802908 [31303/31306]: Dispatching request waiting on sock 20 (in relay_thread_dispatcher() at main.c:995) DEBUG1 - 12:54:41.802936 [31303/31306]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:989) DEBUG1 - 12:54:41.802971 [31303/31307]: Connection socket 20 added (in relay_thread_worker() at main.c:2535) DEBUG3 - 12:54:41.802989 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:41.803024 [31303/31307]: Version check done using protocol 2.9 (in relay_send_version() at main.c:1632) DEBUG3 - 12:54:41.803033 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG3 - 12:54:41.803137 [31303/31307]: Created hashtable size 4 at 0x7fe194000fc0 of type 0 (in lttng_ht_new() at hashtable.c:145) DEBUG1 - 12:54:41.803154 [31303/31307]: Created session 1 (in relay_create_session() at main.c:1105) DEBUG3 - 12:54:41.803171 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:41.803508 [31303/31308]: Relay new connection received (in relay_thread_listener() at main.c:835) DEBUG1 - 12:54:41.803543 [31303/31308]: Relay data connection accepted, socket 21 (in relay_thread_listener() at main.c:874) DEBUG1 - 12:54:41.803560 [31303/31308]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122) DEBUG1 - 12:54:41.803566 [31303/31308]: Listener accepting connections (in relay_thread_listener() at main.c:817) DEBUG1 - 12:54:41.803578 [31303/31306]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105) DEBUG1 - 12:54:41.803584 [31303/31306]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77) DEBUG1 - 12:54:41.803590 [31303/31306]: Dispatching request waiting on sock 21 (in relay_thread_dispatcher() at main.c:995) DEBUG1 - 12:54:41.803605 [31303/31306]: Woken up but nothing in the relay command queue (in relay_thread_dispatcher() at main.c:989) DEBUG1 - 12:54:41.803621 [31303/31307]: Connection socket 21 added (in relay_thread_worker() at main.c:2535) DEBUG3 - 12:54:41.803634 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:41.813698 [31303/31311]: Relay new viewer connection received (in thread_listener() at live.c:537) DEBUG1 - 12:54:41.813733 [31303/31311]: Relay viewer connection accepted socket 22 (in thread_listener() at live.c:573) DEBUG1 - 12:54:41.813751 [31303/31311]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122) DEBUG1 - 12:54:41.813759 [31303/31311]: Listener accepting live viewers connections (in thread_listener() at live.c:520) DEBUG1 - 12:54:41.813772 [31303/31309]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105) DEBUG1 - 12:54:41.813781 [31303/31309]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77) DEBUG1 - 12:54:41.813805 [31303/31309]: Dispatching viewer request waiting on sock 22 (in thread_dispatcher() at live.c:681) DEBUG1 - 12:54:41.813838 [31303/31309]: Woken up but nothing in the live-viewer relay command queue (in thread_dispatcher() at live.c:675) DEBUG1 - 12:54:41.813876 [31303/31310]: Connection socket 22 added to poll (in thread_worker() at live.c:2018) DEBUG3 - 12:54:41.813899 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:41.813915 [31303/31310]: Viewer is establishing a connection to the relayd. (in viewer_connect() at live.c:735) DEBUG1 - 12:54:41.813943 [31303/31310]: Version check done using protocol 2.4 (in viewer_connect() at live.c:797) DEBUG3 - 12:54:41.813951 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:41.813992 [31303/31310]: List sessions received (in viewer_list_sessions() at live.c:823) DEBUG3 - 12:54:41.814031 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:41.830198 [31303/31307]: CTF Trace path /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit not found (in ctf_trace_get_by_path_or_create() at ctf-trace.c:152) DEBUG1 - 12:54:41.830220 [31303/31307]: Created ctf_trace 1 with path: /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit (in ctf_trace_create() at ctf-trace.c:130) DEBUG3 - 12:54:41.830234 [31303/31307]: Created hashtable size 4 at 0x7fe1940017a0 of type 2 (in lttng_ht_new() at hashtable.c:145) DEBUG1 - 12:54:41.830450 [31303/31307]: Tracefile /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/channel0_0 created (in stream_create() at stream.c:148) DEBUG1 - 12:54:41.830463 [31303/31307]: Relay new stream added channel0_0 with ID 1 (in stream_create() at stream.c:174) DEBUG3 - 12:54:41.830489 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG3 - 12:54:41.830589 [31303/31307]: Created hashtable size 4 at 0x7fe194001f70 of type 2 (in lttng_ht_new() at hashtable.c:145) DEBUG1 - 12:54:41.830639 [31303/31307]: Tracefile /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/channel0_1 created (in stream_create() at stream.c:148) DEBUG1 - 12:54:41.830648 [31303/31307]: Relay new stream added channel0_1 with ID 2 (in stream_create() at stream.c:174) DEBUG3 - 12:54:41.830668 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG3 - 12:54:41.831823 [31303/31307]: Created hashtable size 4 at 0x7fe194002650 of type 2 (in lttng_ht_new() at hashtable.c:145) DEBUG1 - 12:54:41.831930 [31303/31307]: Tracefile /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/metadata created (in stream_create() at stream.c:148) DEBUG1 - 12:54:41.831942 [31303/31307]: Relay new stream added metadata with ID 3 (in stream_create() at stream.c:174) DEBUG3 - 12:54:41.831967 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:41.832040 [31303/31307]: Relay receiving streams_sent (in relay_streams_sent() at main.c:2074) DEBUG3 - 12:54:41.832059 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG2 - 12:54:41.839480 [31303/31307]: Relay receiving metadata, waiting for 3773 bytes (in relay_recv_metadata() at main.c:1530) DEBUG1 - 12:54:41.852011 [31303/31310]: Viewer create session received (in viewer_create_session() at live.c:1733) DEBUG3 - 12:54:41.852050 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:41.852090 [31303/31310]: Session find by ID 1 id found (in session_get_by_id() at session.c:122) DEBUG1 - 12:54:41.852101 [31303/31310]: Attach session ID 1 received (in viewer_attach_session() at live.c:1046) DEBUG1 - 12:54:41.852125 [31303/31310]: Relay viewer stream 1 not found (in viewer_stream_get_by_id() at viewer-stream.c:228) DEBUG1 - 12:54:41.852138 [31303/31310]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:41.852145 [31303/31310]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:41.852163 [31303/31310]: Relay viewer stream 2 not found (in viewer_stream_get_by_id() at viewer-stream.c:228) DEBUG1 - 12:54:41.852170 [31303/31310]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:41.852174 [31303/31310]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:41.852179 [31303/31310]: Relay viewer stream 3 not found (in viewer_stream_get_by_id() at viewer-stream.c:228) DEBUG1 - 12:54:41.852185 [31303/31310]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:41.852189 [31303/31310]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:41.852209 [31303/31310]: Sending stream 2 to viewer (in send_viewer_streams() at live.c:250) DEBUG1 - 12:54:41.852223 [31303/31310]: Sending stream 3 to viewer (in send_viewer_streams() at live.c:250) DEBUG1 - 12:54:41.852231 [31303/31310]: Sending stream 1 to viewer (in send_viewer_streams() at live.c:250) DEBUG3 - 12:54:41.852239 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG2 - 12:54:41.876009 [31303/31307]: Relay metadata written. Updated metadata_received 4096 (in relay_recv_metadata() at main.c:1569) DEBUG1 - 12:54:41.876025 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:41.876032 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:41.876039 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:41.892033 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600) DEBUG1 - 12:54:41.892098 [31303/31310]: Sent 4096 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709) DEBUG1 - 12:54:41.892107 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711) DEBUG3 - 12:54:41.892114 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:41.932004 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600) DEBUG1 - 12:54:41.932044 [31303/31310]: Sent 0 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709) DEBUG1 - 12:54:41.932053 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711) DEBUG3 - 12:54:41.932059 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:41.933196 [31303/31310]: Viewer get next index (in viewer_get_next_index() at live.c:1286) DEBUG1 - 12:54:41.933220 [31303/31310]: get next index metadata check: recv 4096 sent 4096 (in viewer_get_next_index() at live.c:1433) DEBUG1 - 12:54:41.933239 [31303/31310]: Index 0 for stream 1 sent (in viewer_get_next_index() at live.c:1454) DEBUG3 - 12:54:41.933246 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:42.335059 [31303/31310]: Viewer get next index (in viewer_get_next_index() at live.c:1286) DEBUG1 - 12:54:42.335353 [31303/31310]: get next index metadata check: recv 4096 sent 4096 (in viewer_get_next_index() at live.c:1433) DEBUG1 - 12:54:42.335555 [31303/31310]: Index 0 for stream 1 sent (in viewer_get_next_index() at live.c:1454) DEBUG3 - 12:54:42.335636 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG3 - 12:54:42.398087 [31303/31307]: Receiving data of size 84 for stream id 1 seqnum 0 (in relay_process_data() at main.c:2288) DEBUG1 - 12:54:42.398753 [31303/31307]: handle_index_data: stream 1 net_seq_num 0 data offset 0 (in handle_index_data() at main.c:2181) DEBUG3 - 12:54:42.398870 [31303/31307]: Finding index for stream id 1 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133) DEBUG2 - 12:54:42.399049 [31303/31307]: Creating relay index for stream id 1 and seqnum 0 (in relay_index_create() at index.c:44) DEBUG2 - 12:54:42.399136 [31303/31307]: Adding relay index with stream id 1 and seqnum 0 (in relay_index_add_unique() at index.c:81) DEBUG2 - 12:54:42.399223 [31303/31307]: Index found or created in HT for stream ID 1 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165) DEBUG1 - 12:54:42.400070 [31303/31307]: utils_unlink_stream_file /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/index/channel0_0.idx returns -1 (in utils_unlink_stream_file() at utils.c:830) DEBUG2 - 12:54:42.400745 [31303/31307]: Relay wrote 84 bytes to tracefile for stream id 1 (in relay_process_data() at main.c:2359) DEBUG1 - 12:54:42.400928 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.400984 [31303/31307]: stream put stream id 1 refcount 4 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.401048 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.401172 [31303/31307]: Relay receiving index (in relay_recv_index() at main.c:1957) DEBUG3 - 12:54:42.401262 [31303/31307]: Finding index for stream id 1 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133) DEBUG2 - 12:54:42.401323 [31303/31307]: Index found or created in HT for stream ID 1 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165) DEBUG2 - 12:54:42.401381 [31303/31307]: Writing index for stream ID 1 and seq num 0 on fd 27 (in relay_index_try_flush() at index.c:300) DEBUG2 - 12:54:42.401464 [31303/31307]: index put for stream id 1 and seqnum 0 refcount 1 (in relay_index_put() at index.c:259) DEBUG1 - 12:54:42.401551 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.401598 [31303/31307]: stream put stream id 1 refcount 4 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.402302 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.402407 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.402715 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG3 - 12:54:42.403456 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG3 - 12:54:42.403637 [31303/31307]: Receiving data of size 10393 for stream id 2 seqnum 0 (in relay_process_data() at main.c:2288) DEBUG1 - 12:54:42.403707 [31303/31307]: handle_index_data: stream 2 net_seq_num 0 data offset 0 (in handle_index_data() at main.c:2181) DEBUG3 - 12:54:42.403763 [31303/31307]: Finding index for stream id 2 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133) DEBUG2 - 12:54:42.403830 [31303/31307]: Creating relay index for stream id 2 and seqnum 0 (in relay_index_create() at index.c:44) DEBUG2 - 12:54:42.403894 [31303/31307]: Adding relay index with stream id 2 and seqnum 0 (in relay_index_add_unique() at index.c:81) DEBUG2 - 12:54:42.403960 [31303/31307]: Index found or created in HT for stream ID 2 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165) DEBUG1 - 12:54:42.404220 [31303/31307]: utils_unlink_stream_file /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/index/channel0_1.idx returns -1 (in utils_unlink_stream_file() at utils.c:830) DEBUG2 - 12:54:42.405246 [31303/31307]: Relay wrote 10393 bytes to tracefile for stream id 2 (in relay_process_data() at main.c:2359) DEBUG1 - 12:54:42.405384 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.405434 [31303/31307]: stream put stream id 2 refcount 4 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.405490 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.405594 [31303/31307]: Relay receiving index (in relay_recv_index() at main.c:1957) DEBUG3 - 12:54:42.406109 [31303/31307]: Finding index for stream id 2 and seq_num 0 (in relay_index_get_by_id_or_create() at index.c:133) DEBUG2 - 12:54:42.406174 [31303/31307]: Index found or created in HT for stream ID 2 and seqnum 0 (in relay_index_get_by_id_or_create() at index.c:165) DEBUG2 - 12:54:42.406230 [31303/31307]: Writing index for stream ID 2 and seq num 0 on fd 28 (in relay_index_try_flush() at index.c:300) DEBUG2 - 12:54:42.406312 [31303/31307]: index put for stream id 2 and seqnum 0 refcount 1 (in relay_index_put() at index.c:259) DEBUG1 - 12:54:42.406392 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.406440 [31303/31307]: stream put stream id 2 refcount 4 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.406531 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.406578 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.406917 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.418993 [31303/31307]: Init streams for data pending (in relay_begin_data_pending() at main.c:1793) DEBUG1 - 12:54:42.419157 [31303/31307]: Set begin data pending flag to stream 2 (in relay_begin_data_pending() at main.c:1833) DEBUG1 - 12:54:42.419217 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.419267 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.419324 [31303/31307]: Set begin data pending flag to stream 3 (in relay_begin_data_pending() at main.c:1833) DEBUG1 - 12:54:42.419369 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.419413 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.419462 [31303/31307]: Set begin data pending flag to stream 1 (in relay_begin_data_pending() at main.c:1833) DEBUG1 - 12:54:42.419506 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.419550 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.419709 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.420443 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651) DEBUG1 - 12:54:42.420574 [31303/31307]: Data pending for stream id 1 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685) DEBUG1 - 12:54:42.420635 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.420682 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.420816 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.421372 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651) DEBUG1 - 12:54:42.421472 [31303/31307]: Data pending for stream id 2 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685) DEBUG1 - 12:54:42.421526 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.421572 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.421694 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.422269 [31303/31307]: Checking quiescent state on control socket (in relay_quiescent_control() at main.c:1730) DEBUG1 - 12:54:42.422381 [31303/31307]: Relay quiescent control pending flag set to 3 (in relay_quiescent_control() at main.c:1759) DEBUG1 - 12:54:42.422434 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.422480 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.422603 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.423119 [31303/31307]: End data pending command (in relay_end_data_pending() at main.c:1872) DEBUG1 - 12:54:42.423228 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.423278 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.423330 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.423374 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.423422 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.423466 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.423592 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.526657 [31303/31307]: Init streams for data pending (in relay_begin_data_pending() at main.c:1793) DEBUG1 - 12:54:42.526860 [31303/31307]: Set begin data pending flag to stream 2 (in relay_begin_data_pending() at main.c:1833) DEBUG1 - 12:54:42.526923 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.526977 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.527037 [31303/31307]: Set begin data pending flag to stream 3 (in relay_begin_data_pending() at main.c:1833) DEBUG1 - 12:54:42.527084 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.527129 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.527178 [31303/31307]: Set begin data pending flag to stream 1 (in relay_begin_data_pending() at main.c:1833) DEBUG1 - 12:54:42.527223 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.527266 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.527449 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.528088 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651) DEBUG1 - 12:54:42.528206 [31303/31307]: Data pending for stream id 1 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685) DEBUG1 - 12:54:42.528265 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.528312 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.528446 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.529116 [31303/31307]: Data pending command received (in relay_data_pending() at main.c:1651) DEBUG1 - 12:54:42.529212 [31303/31307]: Data pending for stream id 2 prev_seq 0 and last_seq 0 (in relay_data_pending() at main.c:1685) DEBUG1 - 12:54:42.529260 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.529304 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.529419 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.529951 [31303/31307]: Checking quiescent state on control socket (in relay_quiescent_control() at main.c:1730) DEBUG1 - 12:54:42.530050 [31303/31307]: Relay quiescent control pending flag set to 3 (in relay_quiescent_control() at main.c:1759) DEBUG1 - 12:54:42.530098 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.530140 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.530261 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.530662 [31303/31307]: End data pending command (in relay_end_data_pending() at main.c:1872) DEBUG1 - 12:54:42.530757 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.530801 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.530967 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.531013 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.531058 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.531098 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.531233 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG2 - 12:54:42.537906 [31303/31307]: Relay receiving metadata, waiting for 49 bytes (in relay_recv_metadata() at main.c:1530) DEBUG2 - 12:54:42.920021 [31303/31307]: Relay metadata written. Updated metadata_received 8192 (in relay_recv_metadata() at main.c:1569) DEBUG1 - 12:54:42.920178 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.920242 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.920314 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.920451 [31303/31307]: Close stream received (in relay_close_stream() at main.c:1248) DEBUG1 - 12:54:42.920622 [31303/31307]: Trying to close stream 3 (in try_stream_close() at stream.c:351) DEBUG1 - 12:54:42.920741 [31303/31307]: Succeeded in closing stream 3 (in try_stream_close() at stream.c:428) DEBUG1 - 12:54:42.920797 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.920843 [31303/31307]: stream put stream id 3 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.920910 [31303/31307]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.920954 [31303/31307]: stream put stream id 3 refcount 2 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.921143 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.120421 [31303/31307]: Close stream received (in relay_close_stream() at main.c:1248) DEBUG1 - 12:54:42.120444 [31303/31307]: Trying to close stream 1 (in try_stream_close() at stream.c:351) DEBUG1 - 12:54:42.120455 [31303/31307]: Succeeded in closing stream 1 (in try_stream_close() at stream.c:428) DEBUG1 - 12:54:42.120460 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.120465 [31303/31307]: stream put stream id 1 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.120470 [31303/31307]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.120474 [31303/31307]: stream put stream id 1 refcount 2 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.120511 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.120668 [31303/31307]: Close stream received (in relay_close_stream() at main.c:1248) DEBUG1 - 12:54:42.120682 [31303/31307]: Trying to close stream 2 (in try_stream_close() at stream.c:351) DEBUG1 - 12:54:42.120689 [31303/31307]: Succeeded in closing stream 2 (in try_stream_close() at stream.c:428) DEBUG1 - 12:54:42.120694 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.120698 [31303/31307]: stream put stream id 2 refcount 3 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.120703 [31303/31307]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.120707 [31303/31307]: stream put stream id 2 refcount 2 (in stream_put() at stream.c:340) DEBUG3 - 12:54:42.120735 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.133819 [31303/31310]: Viewer get next index (in viewer_get_next_index() at live.c:1286) DEBUG1 - 12:54:42.133851 [31303/31310]: Index opening file /tmp/lttng-ivc-e626255q/lttng-traces/ci-node-standalone-amd64-02//trace-20171215-125441//ust/uid/0/64-bit/index/channel0_0.idx in read only (in lttng_index_file_open() at index.c:223) DEBUG1 - 12:54:42.133884 [31303/31310]: Sending viewer index for stream 1 offset 0 (in viewer_get_next_index() at live.c:1414) DEBUG1 - 12:54:42.133901 [31303/31310]: get next index metadata check: recv 8192 sent 4096 (in viewer_get_next_index() at live.c:1433) DEBUG1 - 12:54:42.133924 [31303/31310]: Index 1 for stream 1 sent (in viewer_get_next_index() at live.c:1454) DEBUG3 - 12:54:42.133932 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:42.133991 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600) DEBUG1 - 12:54:42.134023 [31303/31310]: Sent 4096 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709) DEBUG1 - 12:54:42.134030 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711) DEBUG1 - 12:54:42.134044 [31303/31310]: stream put for stream id 3 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.134050 [31303/31310]: stream put stream id 3 refcount 1 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.134056 [31303/31310]: Releasing stream id 3 (in stream_release() at stream.c:293) DEBUG3 - 12:54:42.134086 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:42.152037 [31303/31307]: Control connection closed with 20 (in relay_thread_close_connection() at main.c:2429) DEBUG1 - 12:54:42.152065 [31303/31307]: closing session 1: is conn already closed 0 (in session_close() at session.c:196) DEBUG2 - 12:54:42.152081 [31303/31307]: Relay connection by sock 20 not found (in connection_get_by_sock() at connection.c:56) DEBUG3 - 12:54:42.152088 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.152100 [31303/31307]: Socket 21 did an orderly shutdown (in relay_process_data() at main.c:2267) DEBUG1 - 12:54:42.152131 [31303/31307]: Data connection closed with 21 (in relay_thread_close_connection() at main.c:2429) DEBUG3 - 12:54:42.152141 [31303/31307]: Relayd worker thread polling... (in relay_thread_worker() at main.c:2480) DEBUG1 - 12:54:42.172008 [31303/31310]: Relay get metadata (in viewer_get_metadata() at live.c:1600) DEBUG1 - 12:54:42.172035 [31303/31310]: Relay viewer stream 3 not found (in viewer_stream_get_by_id() at viewer-stream.c:228) DEBUG1 - 12:54:42.172042 [31303/31310]: Client requested metadata of unknown stream id 3 (in viewer_get_metadata() at live.c:1623) DEBUG1 - 12:54:42.172061 [31303/31310]: Sent 0 bytes of metadata for stream 3 (in viewer_get_metadata() at live.c:1709) DEBUG1 - 12:54:42.172067 [31303/31310]: Metadata sent (in viewer_get_metadata() at live.c:1711) DEBUG3 - 12:54:42.172073 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965) DEBUG1 - 12:54:42.173400 [31303/31310]: Viewer control conn closed with 22 (in thread_worker() at live.c:2043) DEBUG1 - 12:54:42.173425 [31303/31310]: stream put for stream id 2 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.173431 [31303/31310]: stream put stream id 2 refcount 1 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.173436 [31303/31310]: Releasing stream id 2 (in stream_release() at stream.c:293) DEBUG1 - 12:54:42.173454 [31303/31310]: stream put for stream id 1 (in stream_put() at stream.c:323) DEBUG1 - 12:54:42.173459 [31303/31310]: stream put stream id 1 refcount 1 (in stream_put() at stream.c:340) DEBUG1 - 12:54:42.173464 [31303/31310]: Releasing stream id 1 (in stream_release() at stream.c:293) DEBUG3 - 12:54:42.173476 [31303/31310]: Relayd live viewer worker thread polling... (in thread_worker() at live.c:1965)
Sessiond log:
libust[31312/31312]: LTT : ltt ring buffer client "relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at lttng-ring-buffer-metadata-client.h:349)
libust[31312/31312]: LTT : ltt ring buffer client "relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at lttng-ring-buffer-client.h:824)
libust[31312/31312]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at lttng-ring-buffer-client.h:824)
libust[31312/31312]: LTT : ltt ring buffer client "relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at lttng-ring-buffer-client.h:824)
libust[31312/31312]: LTT : ltt ring buffer client "relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at lttng-ring-buffer-client.h:824)
DEBUG3 - 12:54:41.657863 [31312/31312]: Agent TCP port set to non default: 58367 (in set_option() at main.c:4898)
DEBUG1 - 12:54:41.658213 [31313/31313]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:541)
DEBUG1 - 12:54:41.658333 [31313/31313]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:602)
DEBUG1 - 12:54:41.658496 [31312/31312]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
DEBUG3 - 12:54:41.658653 [31312/31312]: Creating LTTng run directory: /var/run/lttng (in create_lttng_rundir() at main.c:5268)
DEBUG1 - 12:54:41.658652 [31312/31314]: [ht-thread] startup. (in thread_ht_cleanup() at ht-cleanup.c:101)
DEBUG2 - 12:54:41.658739 [31312/31312]: Kernel consumer err path: /var/run/lttng/kconsumerd/error (in main() at main.c:5735)
DEBUG2 - 12:54:41.658749 [31312/31312]: Kernel consumer cmd path: /var/run/lttng/kconsumerd/command (in main() at main.c:5737)
DEBUG1 - 12:54:41.658746 [31312/31314]: epoll set max size is 821166 (in compat_epoll_set_max_size() at compat-epoll.c:296)
DEBUG1 - 12:54:41.658778 [31312/31312]: Client socket path /var/run/lttng/client-lttng-sessiond (in main() at main.c:5817)
DEBUG1 - 12:54:41.658786 [31312/31312]: Application socket path /var/run/lttng/lttng-ust-sock-7 (in main() at main.c:5818)
DEBUG1 - 12:54:41.658791 [31312/31312]: Application wait path /lttng-ust-wait-7 (in main() at main.c:5819)
DEBUG1 - 12:54:41.658796 [31312/31312]: LTTng run directory path: /var/run/lttng (in main() at main.c:5820)
DEBUG3 - 12:54:41.658797 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG2 - 12:54:41.658837 [31312/31312]: UST consumer 32 bits err path: /var/run/lttng/ustconsumerd32/error (in main() at main.c:5839)
DEBUG2 - 12:54:41.658847 [31312/31312]: UST consumer 32 bits cmd path: /var/run/lttng/ustconsumerd32/command (in main() at main.c:5841)
DEBUG2 - 12:54:41.658868 [31312/31312]: UST consumer 64 bits err path: /var/run/lttng/ustconsumerd64/error (in main() at main.c:5860)
DEBUG2 - 12:54:41.658876 [31312/31312]: UST consumer 64 bits cmd path: /var/run/lttng/ustconsumerd64/command (in main() at main.c:5862)
DEBUG3 - 12:54:41.659029 [31312/31312]: Created hashtable size 4 at 0x17d1250 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.659047 [31312/31312]: Created hashtable size 4 at 0x17d1690 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.659055 [31312/31312]: Created hashtable size 4 at 0x17d1ad0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.659063 [31312/31312]: Created hashtable size 4 at 0x17d27c0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.659069 [31312/31312]: Creating consumer directory: /var/run/lttng/kconsumerd (in set_consumer_sockets() at main.c:5310)
Warning: No tracing group detected
modprobe: FATAL: Module lttng-ring-buffer-client-discard not found in directory /lib/modules/4.4.0-97-generic
Error: Unable to load required module lttng-ring-buffer-client-discard
DEBUG1 - 12:54:41.663308 [31312/31312]: Failed to open /proc/lttng (in init_kernel_tracer() at main.c:2718)
Warning: No kernel tracer available
DEBUG2 - 12:54:41.663328 [31312/31312]: Creating consumer directory: /var/run/lttng/ustconsumerd64 (in set_consumer_sockets() at main.c:5310)
DEBUG2 - 12:54:41.663484 [31312/31312]: Creating consumer directory: /var/run/lttng/ustconsumerd32 (in set_consumer_sockets() at main.c:5310)
DEBUG3 - 12:54:41.663628 [31312/31312]: Session daemon client socket 15 and application socket 16 created (in init_daemon_socket() at main.c:5176)
DEBUG1 - 12:54:41.663697 [31312/31312]: All permissions are set (in set_permissions() at main.c:5256)
DEBUG3 - 12:54:41.663741 [31312/31312]: Created hashtable size 4 at 0x17d51b0 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.663749 [31312/31312]: Global buffer per UID registry initialized (in buffer_reg_init_uid_registry() at buffer-registry.c:99)
DEBUG3 - 12:54:41.663757 [31312/31312]: Created hashtable size 4 at 0x17d5560 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.663763 [31312/31312]: Global buffer per PID registry initialized (in buffer_reg_init_pid_registry() at buffer-registry.c:228)
DEBUG1 - 12:54:41.663770 [31312/31312]: Command subsystem initialized (in cmd_init() at cmd.c:4015)
DEBUG1 - 12:54:41.663808 [31312/31312]: Pid 31312 written in file /var/run/lttng/lttng-sessiond.pid (in utils_create_pid_file() at utils.c:507)
DEBUG1 - 12:54:41.663829 [31312/31312]: Pid 58367 written in file /var/run/lttng/agent.port (in utils_create_pid_file() at utils.c:507)
DEBUG1 - 12:54:41.663905 [31312/31312]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547)
DEBUG1 - 12:54:41.663995 [31312/31318]: [thread] Manage health check started (in thread_manage_health() at main.c:4159)
DEBUG1 - 12:54:41.664025 [31312/31319]: [thread] Manage client started (in thread_manage_clients() at main.c:4350)
DEBUG1 - 12:54:41.675072 [31312/31322]: [thread] Manage application started (in thread_manage_apps() at main.c:1555)
DEBUG1 - 12:54:41.672333 [31312/31320]: [thread] Dispatch UST command started (in thread_dispatch_ust_registration() at main.c:1869)
DEBUG1 - 12:54:41.675769 [31312/31320]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.675780 [31312/31320]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1896)
DEBUG1 - 12:54:41.664162 [31312/31321]: [thread] Manage application registration started (in thread_registration_apps() at main.c:2114)
DEBUG1 - 12:54:41.675980 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.676028 [31312/31323]: [ust-thread] Manage application notify command (in ust_thread_manage_notify() at ust-thread.c:40)
DEBUG1 - 12:54:41.676028 [31312/31321]: Notifying applications of session daemon state: 1 (in notify_ust_apps() at main.c:804)
DEBUG1 - 12:54:41.676157 [31312/31318]: Health check ready (in thread_manage_health() at main.c:4221)
DEBUG1 - 12:54:41.676079 [31312/31321]: Got the wait shm fd 29 (in get_wait_shm() at shm.c:115)
DEBUG1 - 12:54:41.676213 [31312/31321]: Futex wait update active 1 (in futex_wait_update() at futex.c:65)
DEBUG1 - 12:54:41.676220 [31312/31321]: Accepting application registration (in thread_registration_apps() at main.c:2151)
DEBUG1 - 12:54:41.676236 [31312/31322]: Apps thread polling (in thread_manage_apps() at main.c:1585)
DEBUG1 - 12:54:41.676250 [31312/31324]: [agent-thread] Manage agent application registration. (in agent_thread_manage_registration() at agent-thread.c:236)
DEBUG3 - 12:54:41.676265 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG1 - 12:54:41.676289 [31312/31325]: [thread] Thread manage kernel started (in thread_manage_kernel() at main.c:1053)
DEBUG3 - 12:54:41.676293 [31312/31324]: URI string: tcp://localhost (in uri_parse() at uri.c:324)
DEBUG1 - 12:54:41.676319 [31312/31326]: [load-session-thread] Load session (in thread_load_session() at load-session-thread.c:91)
DEBUG1 - 12:54:41.676384 [31312/31325]: Updating kernel poll set (in update_kernel_poll() at main.c:888)
DEBUG1 - 12:54:41.676396 [31312/31325]: Thread kernel polling (in thread_manage_kernel() at main.c:1098)
DEBUG2 - 12:54:41.681057 [31312/31324]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
DEBUG3 - 12:54:41.681075 [31312/31324]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 0, data: 0 (in uri_parse() at uri.c:538)
DEBUG1 - 12:54:41.681105 [31312/31324]: [agent-thread] Listening on TCP port 58367 and socket 31 (in init_tcp_socket() at agent-thread.c:119)
DEBUG3 - 12:54:41.681115 [31312/31324]: [agent-thread] Manage agent polling (in agent_thread_manage_registration() at agent-thread.c:263)
DEBUG1 - 12:54:41.686839 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.686883 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.686907 [31312/31319]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4498)
DEBUG1 - 12:54:41.686920 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.686926 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.687356 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.687381 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.687423 [31312/31319]: Processing client command 30 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.687451 [31312/31319]: Waiting for 2 URIs from client ... (in process_client_msg() at main.c:4077)
DEBUG2 - 12:54:41.687479 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:41.687505 [31312/31319]: Created hashtable size 4 at 0x7fab0c008f10 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.687512 [31312/31319]: Allocating ltt_sessions_ht_by_id (in ltt_sessions_ht_alloc() at session.c:153)
DEBUG3 - 12:54:41.687518 [31312/31319]: Created hashtable size 4 at 0x7fab0c009350 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.687527 [31312/31319]: Tracing session trace created with ID 0 by UID 0 GID 0 (in session_create() at session.c:420)
DEBUG2 - 12:54:41.687533 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:41.687557 [31312/31319]: Created hashtable size 4 at 0x7fab0c00e800 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.687563 [31312/31319]: Setting network URI to consumer (in add_uri_to_consumer() at cmd.c:718)
DEBUG3 - 12:54:41.687570 [31312/31319]: Consumer control URI set with port 38120 (in consumer_set_network_uri() at consumer.c:659)
DEBUG3 - 12:54:41.687583 [31312/31319]: Consumer set network uri subdir path ci-node-standalone-amd64-02/ (in consumer_set_network_uri() at consumer.c:722)
DEBUG2 - 12:54:41.687601 [31312/31319]: Consumer subdir set to ci-node-standalone-amd64-02//trace-20171215-125441/ (in consumer_set_subdir() at consumer.c:1097)
DEBUG3 - 12:54:41.687608 [31312/31319]: Append domain trace name to subdir ci-node-standalone-amd64-02//trace-20171215-125441/ (in add_uri_to_consumer() at cmd.c:760)
DEBUG2 - 12:54:41.687613 [31312/31319]: Setting network URI to consumer (in add_uri_to_consumer() at cmd.c:718)
DEBUG3 - 12:54:41.687617 [31312/31319]: Consumer data URI set with port 42335 (in consumer_set_network_uri() at consumer.c:674)
DEBUG1 - 12:54:41.687625 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:41.687640 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.687645 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.696439 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.696469 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.696505 [31312/31319]: Processing client command 6 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.696522 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:41.696528 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:41.696534 [31312/31319]: Creating UST session (in create_ust_session() at main.c:2856)
DEBUG3 - 12:54:41.696547 [31312/31319]: Created hashtable size 4 at 0x7fab0c005ea0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.696555 [31312/31319]: Created hashtable size 4 at 0x7fab0c0062e0 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.696591 [31312/31319]: Created hashtable size 4 at 0x7fab0c006720 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.696597 [31312/31319]: UST trace session create successful (in trace_ust_create_session() at trace-ust.c:320)
DEBUG3 - 12:54:41.696603 [31312/31319]: Copying tracing session consumer output in UST session (in copy_session_consumer() at main.c:2803)
DEBUG3 - 12:54:41.696632 [31312/31319]: Created hashtable size 4 at 0x7fab0c006b60 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.696643 [31312/31319]: Copy session consumer subdir ci-node-standalone-amd64-02//trace-20171215-125441//ust (in copy_session_consumer() at main.c:2821)
DEBUG1 - 12:54:41.696651 [31312/31319]: Spawning consumerd (in spawn_consumerd() at main.c:2491)
DEBUG3 - 12:54:41.696680 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG2 - 12:54:41.697073 [31312/31319]: Consumer pid 31329 (in start_consumerd() at main.c:2676)
DEBUG2 - 12:54:41.697127 [31312/31319]: Spawning consumer control thread (in start_consumerd() at main.c:2679)
DEBUG1 - 12:54:41.697232 [31312/31330]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1227)
DEBUG1 - 12:54:41.698790 [31329/31329]: Using 64-bit UST consumer at: /root/workspace/lttng-ivc-master-modules/arch/x86-64/liburcu_version/master/slave/x86-64-standalone/src/lttng_ivc/runtime/projects_cache/lttng-tools-2.9/install/lib/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2571)
libust[31329/31329]: LTT : ltt ring buffer client "relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at lttng-ring-buffer-metadata-client.h:349)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at lttng-ring-buffer-client.h:824)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at lttng-ring-buffer-client.h:824)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at lttng-ring-buffer-client.h:824)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at lttng-ring-buffer-client.h:824)
DEBUG1 - 12:54:41.700892 [31329/31329]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
DEBUG1 - 12:54:41.701077 [31329/31329]: TCP inet operation timeout set to 216 sec (in lttcomm_inet_init() at inet.c:547)
DEBUG1 - 12:54:41.701314 [31332/31332]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:541)
DEBUG1 - 12:54:41.701399 [31332/31332]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:602)
DEBUG1 - 12:54:41.701521 [31329/31329]: Connecting to error socket /var/run/lttng/ustconsumerd64/error (in main() at lttng-consumerd.c:464)
DEBUG2 - 12:54:41.701593 [31312/31330]: Receiving code from consumer err_sock (in thread_manage_consumer() at main.c:1325)
DEBUG1 - 12:54:41.701698 [31329/31333]: [thread] Manage health check started (in thread_manage_health() at health-consumerd.c:167)
Warning: No tracing group detected
DEBUG1 - 12:54:41.702675 [31329/31333]: epoll set max size is 821166 (in compat_epoll_set_max_size() at compat-epoll.c:296)
DEBUG1 - 12:54:41.702697 [31329/31333]: Health check ready (in thread_manage_health() at health-consumerd.c:240)
DEBUG3 - 12:54:41.707313 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG1 - 12:54:41.802365 [31329/31336]: Thread metadata poll started (in consumer_thread_metadata_poll() at consumer.c:2245)
DEBUG1 - 12:54:41.802399 [31329/31335]: Thread channel poll started (in consumer_thread_channel_poll() at consumer.c:2829)
DEBUG1 - 12:54:41.802429 [31329/31336]: Metadata main loop started (in consumer_thread_metadata_poll() at consumer.c:2261)
DEBUG1 - 12:54:41.802467 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG1 - 12:54:41.802489 [31329/31337]: Updating poll fd array (in update_poll_array() at consumer.c:1085)
DEBUG1 - 12:54:41.802512 [31329/31337]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:41.802492 [31329/31338]: Creating command socket /var/run/lttng/ustconsumerd64/command (in consumer_thread_sessiond_poll() at consumer.c:3097)
DEBUG1 - 12:54:41.802431 [31329/31335]: Channel main loop started (in consumer_thread_channel_poll() at consumer.c:2844)
DEBUG1 - 12:54:41.802558 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:41.802564 [31329/31338]: Sending ready command to lttng-sessiond (in consumer_thread_sessiond_poll() at consumer.c:3110)
DEBUG3 - 12:54:41.802645 [31312/31319]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 12:54:41.802664 [31312/31319]: Setting relayd for session trace (in cmd_setup_relayd() at cmd.c:1014)
DEBUG3 - 12:54:41.802685 [31312/31319]: Relayd connect ... (in relayd_connect() at relayd.c:494)
DEBUG3 - 12:54:41.802783 [31312/31319]: Creating relayd stream socket from URI (in create_connect_relayd() at cmd.c:855)
DEBUG1 - 12:54:41.802795 [31312/31319]: Relayd version check for major.minor 2.9 (in relayd_version_check() at relayd.c:392)
DEBUG3 - 12:54:41.802823 [31312/31319]: Relayd sending command 5 of size 32 (in send_command() at relayd.c:81)
DEBUG3 - 12:54:41.802830 [31312/31319]: Relayd waiting for reply of size 8 (in recv_reply() at relayd.c:101)
DEBUG1 - 12:54:41.802844 [31312/31330]: Consumer command socket ready (fd: 35 (in thread_manage_consumer() at main.c:1358)
DEBUG1 - 12:54:41.802850 [31312/31330]: Consumer metadata socket ready (fd: 36) (in thread_manage_consumer() at main.c:1360)
DEBUG1 - 12:54:41.802870 [31329/31338]: Connection on client_socket (in consumer_thread_sessiond_poll() at consumer.c:3132)
DEBUG1 - 12:54:41.802889 [31329/31338]: Metadata connection on client_socket (in set_metadata_socket() at consumer.c:3058)
DEBUG2 - 12:54:41.803053 [31312/31319]: Relayd version is compatible, using protocol version 2.9 (in relayd_version_check() at relayd.c:440)
DEBUG1 - 12:54:41.803070 [31312/31319]: Relayd create session (in relayd_create_session() at relayd.c:189)
DEBUG3 - 12:54:41.803096 [31312/31319]: Relayd sending command 2 of size 351 (in send_command() at relayd.c:81)
DEBUG3 - 12:54:41.803104 [31312/31319]: Relayd waiting for reply of size 12 (in recv_reply() at relayd.c:101)
DEBUG1 - 12:54:41.803188 [31312/31319]: Relayd session created with id 1 (in relayd_create_session() at relayd.c:227)
DEBUG3 - 12:54:41.803197 [31312/31319]: Sending relayd sock info to consumer on 35 (in consumer_send_relayd_socket() at consumer.c:1033)
DEBUG1 - 12:54:41.803222 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.803251 [31329/31338]: Consumer adding relayd socket (idx: 2) (in consumer_add_relayd_socket() at consumer.c:3359)
DEBUG3 - 12:54:41.803296 [31312/31319]: Sending relayd socket file descriptor to consumer (in consumer_send_relayd_socket() at consumer.c:1039)
DEBUG1 - 12:54:41.803343 [31329/31338]: Consumer control socket created successfully with net idx 2 (fd: -1) (in consumer_add_relayd_socket() at consumer.c:3489)
DEBUG2 - 12:54:41.803362 [31312/31319]: Consumer relayd socket sent (in consumer_send_relayd_socket() at consumer.c:1045)
DEBUG3 - 12:54:41.803379 [31312/31319]: Relayd closing socket 37 (in relayd_close() at relayd.c:525)
DEBUG3 - 12:54:41.803393 [31312/31319]: Relayd connect ... (in relayd_connect() at relayd.c:494)
DEBUG3 - 12:54:41.803451 [31312/31319]: Creating relayd data socket from URI (in create_connect_relayd() at cmd.c:866)
DEBUG3 - 12:54:41.803463 [31312/31319]: Sending relayd sock info to consumer on 35 (in consumer_send_relayd_socket() at consumer.c:1033)
DEBUG1 - 12:54:41.803490 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.803501 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.803520 [31329/31338]: Consumer adding relayd socket (idx: 2) (in consumer_add_relayd_socket() at consumer.c:3359)
DEBUG3 - 12:54:41.803536 [31312/31319]: Sending relayd socket file descriptor to consumer (in consumer_send_relayd_socket() at consumer.c:1039)
DEBUG1 - 12:54:41.803600 [31329/31338]: Consumer data socket created successfully with net idx 2 (fd: -1) (in consumer_add_relayd_socket() at consumer.c:3489)
DEBUG2 - 12:54:41.803662 [31312/31319]: Consumer relayd socket sent (in consumer_send_relayd_socket() at consumer.c:1045)
DEBUG3 - 12:54:41.803671 [31312/31319]: Relayd closing socket 37 (in relayd_close() at relayd.c:525)
DEBUG1 - 12:54:41.803684 [31312/31319]: Enable event command for event 'tp:tptest' (in _cmd_enable_event() at cmd.c:1822)
DEBUG2 - 12:54:41.803694 [31312/31319]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
DEBUG1 - 12:54:41.803704 [31312/31319]: Enabling channel for session trace (in cmd_enable_channel() at cmd.c:1317)
DEBUG2 - 12:54:41.803709 [31312/31319]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
DEBUG3 - 12:54:41.803721 [31312/31319]: Created hashtable size 4 at 0x7fab0c007240 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.803729 [31312/31319]: Created hashtable size 4 at 0x7fab0c007610 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.803734 [31312/31319]: Trace UST channel channel0 created (in trace_ust_create_channel() at trace-ust.c:391)
DEBUG2 - 12:54:41.803741 [31312/31319]: Channel channel0 is being created for UST with buffer 1 and id 0 (in channel_ust_create() at channel.c:413)
DEBUG2 - 12:54:41.803747 [31312/31319]: UST app adding channel channel0 to UST domain for session id 0 (in ust_app_create_channel_glb() at ust-app.c:4074)
DEBUG2 - 12:54:41.803757 [31312/31319]: Channel channel0 created successfully (in channel_ust_create() at channel.c:448)
DEBUG2 - 12:54:41.803763 [31312/31319]: Trace UST channel channel0 found by name (in trace_ust_find_channel_by_name() at trace-ust.c:191)
DEBUG2 - 12:54:41.803770 [31312/31319]: Trace UST event tp:tptest NOT found (in trace_ust_find_event() at trace-ust.c:234)
DEBUG2 - 12:54:41.803776 [31312/31319]: Trace UST event tp:tptest, loglevel (0,-1) created (in trace_ust_create_event() at trace-ust.c:508)
DEBUG1 - 12:54:41.803781 [31312/31319]: UST app creating event tp:tptest for all apps for session id 0 (in ust_app_create_event_glb() at ust-app.c:4258)
DEBUG1 - 12:54:41.803788 [31312/31319]: Event UST tp:tptest created in channel channel0 (in event_ust_enable_tracepoint() at event.c:236)
DEBUG1 - 12:54:41.803799 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:41.803820 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.803826 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.804241 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.819907 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.819960 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.820003 [31312/31319]: Processing client command 16 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.820014 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:41.820020 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:41.820031 [31312/31319]: Starting all UST traces (in ust_app_start_trace_all() at ust-app.c:4859)
DEBUG1 - 12:54:41.820036 [31312/31319]: Clearing stream quiescent state for all ust apps (in ust_app_clear_quiescent_session() at ust-app.c:4734)
DEBUG1 - 12:54:41.820044 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:41.820073 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:41.820081 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:41.827601 [31312/31321]: UST registration received with pid:31341 ppid:24820 uid:0 gid:0 sock:32 name:app-ust (version 7.1) (in thread_registration_apps() at main.c:2267)
DEBUG1 - 12:54:41.827645 [31312/31321]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.827654 [31312/31321]: Accepting application registration (in thread_registration_apps() at main.c:2151)
DEBUG1 - 12:54:41.827666 [31312/31320]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.827690 [31312/31320]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.827699 [31312/31320]: Dispatching UST registration pid:31341 ppid:24820 uid:0 gid:0 sock:32 name:app-ust (version 7.1) (in thread_dispatch_ust_registration() at main.c:1908)
DEBUG3 - 12:54:41.827726 [31312/31320]: UST app creating application for socket 32 (in ust_app_create() at ust-app.c:3295)
DEBUG1 - 12:54:41.827724 [31312/31321]: UST registration received with pid:31341 ppid:24820 uid:0 gid:0 sock:37 name:app-ust (version 7.1) (in thread_registration_apps() at main.c:2267)
DEBUG3 - 12:54:41.827750 [31312/31320]: Created hashtable size 4 at 0x7fab00000a40 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.827755 [31312/31321]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
DEBUG1 - 12:54:41.827763 [31312/31321]: Accepting application registration (in thread_registration_apps() at main.c:2151)
DEBUG3 - 12:54:41.827764 [31312/31320]: Created hashtable size 4 at 0x7fab00000e80 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.827773 [31312/31320]: Created hashtable size 4 at 0x7fab000012c0 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG1 - 12:54:41.827793 [31312/31320]: Dispatching UST registration pid:31341 ppid:24820 uid:0 gid:0 sock:37 name:app-ust (version 7.1) (in thread_dispatch_ust_registration() at main.c:1908)
DEBUG3 - 12:54:41.827801 [31312/31320]: UST app notify socket 37 is set (in thread_dispatch_ust_registration() at main.c:1965)
DEBUG1 - 12:54:41.827813 [31312/31320]: App registered with pid:31341 ppid:24820 uid:0 gid:0 sock:32 name:app-ust notify_sock:37 (version 7.1) (in ust_app_add() at ust-app.c:3384)
libust[31312/31320]: received tracer version (in ustctl_tracer_version() at ustctl.c:523)
DEBUG2 - 12:54:41.828013 [31312/31320]: UST app global update for app sock 32 for session id 0 (in ust_app_global_update() at ust-app.c:5056)
DEBUG2 - 12:54:41.828026 [31312/31320]: UST app pid: 31341 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2164)
DEBUG3 - 12:54:41.828048 [31312/31320]: Created hashtable size 4 at 0x7fab00004810 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.828072 [31312/31320]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1862)
DEBUG2 - 12:54:41.828088 [31312/31320]: Channel channel0 not found on shadow session copy, creating it (in shadow_copy_session() at ust-app.c:1947)
DEBUG3 - 12:54:41.828099 [31312/31320]: Created hashtable size 4 at 0x7fab00004e90 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828115 [31312/31320]: Created hashtable size 4 at 0x7fab000052d0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828121 [31312/31320]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1044)
DEBUG2 - 12:54:41.828127 [31312/31320]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1787)
DEBUG2 - 12:54:41.828133 [31312/31320]: UST event tp:tptest not found on shadow copy channel (in shadow_copy_channel() at ust-app.c:1828)
DEBUG3 - 12:54:41.828139 [31312/31320]: UST app event tp:tptest allocated (in alloc_ust_app_event() at ust-app.c:1100)
DEBUG3 - 12:54:41.828147 [31312/31320]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1838)
DEBUG3 - 12:54:41.828154 [31312/31320]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.828174 [31312/31320]: Created hashtable size 4 at 0x7fab00007b20 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828180 [31312/31320]: Buffer registry per UID created id: 0, ABI: 64, uid: 0, domain: 2 (in buffer_reg_uid_create() at buffer-registry.c:152)
DEBUG3 - 12:54:41.828203 [31312/31320]: Created hashtable size 4 at 0x7fab0000b030 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828210 [31312/31320]: Created hashtable size 4 at 0x7fab0000b470 of type 2 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.828256 [31312/31320]: Append to metadata: "/* CTF 1.8 */
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828279 [31312/31320]: Append to metadata: "typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
typealias integer { size = 27; align = 1; signed = false; } := uint27_t;
trace {
major = 1;
minor = 8;
uuid = "002be8c6-8430-436b-b30e-777f39fb530b";
byte_order = le;
packet.header := struct {
uint32_t magic;
uint8_t uuid[16];
uint32_t stream_id;
uint64_t stream_instance_id;
};
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828290 [31312/31320]: Append to metadata: "env {
hostname = "ci-node-standalone-amd64-02";
domain = "ust";
tracer_name = "lttng-ust";
tracer_major = 2;
tracer_minor = 9;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828296 [31312/31320]: Append to metadata: "};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828302 [31312/31320]: Append to metadata: "clock {
name = "monotonic";
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828329 [31312/31320]: Append to metadata: " uuid = "127e7c0f-63fd-4aa9-897c-20c67bbb6669";
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828343 [31312/31320]: Append to metadata: " description = "Monotonic Clock";
freq = 1000000000; /* Frequency, in Hz */
/* clock value offset from Epoch is: offset * (1/freq) */
offset = 1513359486047831535;
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828353 [31312/31320]: Append to metadata: "typealias integer {
size = 27; align = 1; signed = false;
map = clock.monotonic.value;
} := uint27_clock_monotonic_t;
typealias integer {
size = 32; align = 8; signed = false;
map = clock.monotonic.value;
} := uint32_clock_monotonic_t;
typealias integer {
size = 64; align = 8; signed = false;
map = clock.monotonic.value;
} := uint64_clock_monotonic_t;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828360 [31312/31320]: Append to metadata: "struct packet_context {
uint64_clock_monotonic_t timestamp_begin;
uint64_clock_monotonic_t timestamp_end;
uint64_t content_size;
uint64_t packet_size;
uint64_t packet_seq_num;
unsigned long events_discarded;
uint32_t cpu_id;
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828380 [31312/31320]: Append to metadata: "struct event_header_compact {
enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
variant <id> {
struct {
uint27_clock_monotonic_t timestamp;
} compact;
struct {
uint32_t id;
uint64_clock_monotonic_t timestamp;
} extended;
} v;
} align(8);
struct event_header_large {
enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
variant <id> {
struct {
uint32_clock_monotonic_t timestamp;
} compact;
struct {
uint32_t id;
uint64_clock_monotonic_t timestamp;
} extended;
} v;
} align(8);
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.828388 [31312/31320]: Buffer registry per UID adding to global registry with id: 0 (in buffer_reg_uid_add() at buffer-registry.c:174)
DEBUG3 - 12:54:41.828396 [31312/31320]: UST app buffer registry per UID created successfully (in setup_buffer_reg_uid() at ust-app.c:2127)
DEBUG3 - 12:54:41.828439 [31312/31323]: [ust-thread] Manage notify return from poll on 2 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.828455 [31312/31323]: UST thread notify added sock 37 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
DEBUG3 - 12:54:41.828461 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
libust[31312/31320]: received session handle 1 (in ustctl_create_session() at ustctl.c:178)
DEBUG2 - 12:54:41.828760 [31312/31320]: UST app session created successfully with handle 1 (in create_ust_app_session() at ust-app.c:2239)
DEBUG1 - 12:54:41.828771 [31312/31320]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2855)
DEBUG3 - 12:54:41.828776 [31312/31320]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG2 - 12:54:41.828784 [31312/31320]: UST app creating buffer registry channel for channel0 (in create_buffer_reg_channel() at ust-app.c:2700)
DEBUG3 - 12:54:41.828789 [31312/31320]: Buffer registry channel create with key: 0 (in buffer_reg_channel_create() at buffer-registry.c:380)
DEBUG3 - 12:54:41.828800 [31312/31320]: Created hashtable size 4 at 0x7fab0000b9d0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG2 - 12:54:41.828811 [31312/31320]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:120)
DEBUG3 - 12:54:41.828833 [31312/31320]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:784)
DEBUG1 - 12:54:41.828868 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.828907 [31329/31338]: Allocated channel (key 1) (in consumer_allocate_channel() at consumer.c:1025)
DEBUG1 - 12:54:41.829894 [31329/31338]: UST consumer add stream channel0_0 (key: 32) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 12:54:41.829909 [31329/31338]: UST consumer add stream channel0_1 (key: 34) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 12:54:41.829948 [31329/31338]: UST consumer channel added (key: 1) (in add_channel() at ust-consumer.c:115)
DEBUG1 - 12:54:41.829963 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG2 - 12:54:41.829984 [31312/31320]: UST ask channel 1 successfully done with 2 stream(s) (in ask_channel_creation() at ust-consumer.c:215)
DEBUG1 - 12:54:41.830002 [31329/31335]: Channel poll return from wait with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:41.830031 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:41.830016 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.830050 [31329/31335]: Adding channel 29 to poll set (in consumer_thread_channel_poll() at consumer.c:2898)
DEBUG1 - 12:54:41.830073 [31329/31338]: UST consumer sending channel channel0 to sessiond (in send_sessiond_channel() at ust-consumer.c:562)
DEBUG1 - 12:54:41.830094 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:41.830106 [31329/31338]: Relayd adding stream for channel name channel0_0 (in relayd_add_stream() at relayd.c:252)
DEBUG1 - 12:54:41.830508 [31329/31338]: Relayd stream added successfully with handle 1 (in relayd_add_stream() at relayd.c:317)
DEBUG1 - 12:54:41.830519 [31329/31338]: Stream channel0_0 with key 32 sent to relayd id 2 (in consumer_send_relayd_stream() at consumer.c:812)
DEBUG1 - 12:54:41.830529 [31329/31338]: Relayd adding stream for channel name channel0_1 (in relayd_add_stream() at relayd.c:252)
DEBUG1 - 12:54:41.830688 [31329/31338]: Relayd stream added successfully with handle 2 (in relayd_add_stream() at relayd.c:317)
DEBUG1 - 12:54:41.830698 [31329/31338]: Stream channel0_1 with key 34 sent to relayd id 2 (in consumer_send_relayd_stream() at consumer.c:812)
DEBUG1 - 12:54:41.830719 [31329/31338]: UST consumer sending stream 32 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
DEBUG1 - 12:54:41.830730 [31329/31338]: UST consumer sending stream 34 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
DEBUG1 - 12:54:41.830740 [31329/31338]: UST consumer NULL stream sent to sessiond (in send_sessiond_channel() at ust-consumer.c:626)
DEBUG1 - 12:54:41.830843 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.830854 [31329/31337]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:41.830879 [31329/31337]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2555)
DEBUG2 - 12:54:41.830886 [31312/31320]: UST app stream 1 received successfully (in ust_consumer_get_channel() at ust-consumer.c:330)
DEBUG1 - 12:54:41.830892 [31329/31337]: Updating poll fd array (in update_poll_array() at consumer.c:1085)
DEBUG1 - 12:54:41.830907 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG2 - 12:54:41.830909 [31312/31320]: UST app stream 2 received successfully (in ust_consumer_get_channel() at ust-consumer.c:330)
DEBUG1 - 12:54:41.830914 [31329/31337]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:41.830920 [31329/31337]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2555)
DEBUG3 - 12:54:41.830922 [31312/31320]: UST app consumer has no more stream available (in ust_consumer_get_channel() at ust-consumer.c:313)
DEBUG1 - 12:54:41.830926 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG2 - 12:54:41.830932 [31312/31320]: UST app setup buffer registry channel for channel0 (in setup_buffer_reg_channel() at ust-app.c:2750)
DEBUG2 - 12:54:41.830939 [31312/31320]: UST app setup buffer registry stream (in setup_buffer_reg_streams() at ust-app.c:2655)
DEBUG3 - 12:54:41.830945 [31312/31320]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
DEBUG3 - 12:54:41.830952 [31312/31320]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
DEBUG1 - 12:54:41.830957 [31312/31320]: UST app sending buffer registry channel to ust sock 32 (in send_channel_uid_to_ust() at ust-app.c:2786)
DEBUG2 - 12:54:41.830965 [31312/31320]: UST app send channel to sock 32 pid 31341 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:436)
DEBUG2 - 12:54:41.831137 [31312/31320]: UST consumer send stream to app 32 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:399)
DEBUG2 - 12:54:41.831214 [31312/31320]: UST consumer send stream to app 32 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:399)
libust[31312/31320]: received event handle 3 (in ustctl_create_event() at ustctl.c:212)
DEBUG2 - 12:54:41.831333 [31312/31320]: UST app event tp:tptest created successfully for pid:31341 (in create_ust_event() at ust-app.c:1687)
libust[31312/31320]: enabled handle 3 (in ustctl_enable() at ustctl.c:381)
DEBUG2 - 12:54:41.831428 [31312/31320]: UST app event tp:tptest enabled successfully for app (pid: 31341) (in enable_ust_event() at ust-app.c:1591)
DEBUG1 - 12:54:41.831437 [31312/31320]: Starting tracing for ust app pid 31341 (in ust_app_start_trace() at ust-app.c:4322)
DEBUG3 - 12:54:41.831444 [31312/31320]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.831458 [31312/31320]: Created hashtable size 4 at 0x7fab0000df00 of type 1 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.831465 [31312/31320]: Created hashtable size 4 at 0x7fab0000e2e0 of type 0 (in lttng_ht_new() at hashtable.c:145)
DEBUG3 - 12:54:41.831470 [31312/31320]: UST app channel metadata allocated (in alloc_ust_app_channel() at ust-app.c:1044)
DEBUG2 - 12:54:41.831478 [31312/31320]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:120)
DEBUG1 - 12:54:41.831510 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.831542 [31329/31338]: Allocated channel (key 2) (in consumer_allocate_channel() at consumer.c:1025)
DEBUG1 - 12:54:41.831645 [31329/31338]: UST consumer add stream metadata (key: 40) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
DEBUG1 - 12:54:41.831657 [31329/31338]: Allocated metadata cache of 4096 bytes (in consumer_metadata_cache_allocate() at consumer-metadata-cache.c:198)
DEBUG1 - 12:54:41.831668 [31329/31338]: UST consumer channel added (key: 2) (in add_channel() at ust-consumer.c:115)
DEBUG1 - 12:54:41.831677 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG2 - 12:54:41.831694 [31312/31320]: UST ask channel 2 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:215)
DEBUG2 - 12:54:41.831706 [31312/31320]: Consumer setup metadata channel key 2 (in consumer_setup_metadata() at consumer.c:1273)
DEBUG1 - 12:54:41.831727 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.831742 [31329/31338]: UST consumer setup metadata key 2 (in setup_metadata() at ust-consumer.c:876)
DEBUG1 - 12:54:41.831752 [31329/31338]: Relayd adding stream for channel name metadata (in relayd_add_stream() at relayd.c:252)
DEBUG1 - 12:54:41.831990 [31329/31338]: Relayd stream added successfully with handle 3 (in relayd_add_stream() at relayd.c:317)
DEBUG1 - 12:54:41.832002 [31329/31338]: Stream metadata with key 40 sent to relayd id 2 (in consumer_send_relayd_stream() at consumer.c:812)
DEBUG1 - 12:54:41.832010 [31329/31338]: Relayd sending streams sent. (in relayd_streams_sent() at relayd.c:336)
DEBUG1 - 12:54:41.832072 [31329/31338]: Relayd streams sent success (in relayd_streams_sent() at relayd.c:369)
DEBUG1 - 12:54:41.832081 [31329/31338]: All streams sent relayd id 2 (in consumer_send_relayd_streams_sent() at consumer.c:850)
DEBUG1 - 12:54:41.832105 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:41.832117 [31329/31336]: Metadata poll return from wait with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:41.832123 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:41.832131 [31329/31336]: Adding metadata stream 40 to poll set (in consumer_thread_metadata_poll() at consumer.c:2326)
DEBUG1 - 12:54:41.832139 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG2 - 12:54:41.832152 [31312/31320]: UST metadata with key 2 created for app pid 31341 (in create_ust_app_metadata() at ust-app.c:3246)
DEBUG3 - 12:54:41.832164 [31312/31320]: UST app deleting channel metadata (in delete_ust_app_channel() at ust-app.c:457)
DEBUG3 - 12:54:41.832339 [31312/31323]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.832362 [31312/31323]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5629)
DEBUG2 - 12:54:41.832371 [31312/31323]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5683)
DEBUG3 - 12:54:41.832394 [31312/31323]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.832403 [31312/31323]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:784)
DEBUG3 - 12:54:41.832414 [31312/31323]: Append to metadata: "stream {
id = 0;
event.header := struct event_header_compact;
packet.context := struct packet_context;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.832421 [31312/31323]: Append to metadata: "};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.832426 [31312/31323]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5409)
DEBUG3 - 12:54:41.832444 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
libust[31312/31320]: enabled handle 1 (in ustctl_enable() at ustctl.c:381)
libust[31312/31320]: waited for quiescent state (in ustctl_wait_quiescent() at ustctl.c:539)
DEBUG2 - 12:54:41.832628 [31312/31320]: UST trace started for app pid 31341 (in ust_app_global_create() at ust-app.c:5018)
libust[31312/31320]: Sending register done command to 32 (in ustctl_register_done() at ustctl.c:151)
DEBUG3 - 12:54:41.834141 [31312/31323]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.834158 [31312/31323]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5629)
DEBUG2 - 12:54:41.834167 [31312/31323]: UST app ustctl register event received (in ust_app_recv_notify() at ust-app.c:5649)
DEBUG3 - 12:54:41.834201 [31312/31323]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:41.834211 [31312/31323]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:784)
DEBUG3 - 12:54:41.834219 [31312/31323]: UST registry creating event with event: tp:tptest, sig: int, anint, int, netint, long *, values, char *, text, size_t, textlen, double, doublearg, float, floatarg, id: 0, chan_objd: 2, sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:424)
DEBUG3 - 12:54:41.834232 [31312/31323]: Append to metadata: "event {
name = "tp:tptest";
id = 0;
stream_id = 0;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834240 [31312/31323]: Append to metadata: " loglevel = 13;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834245 [31312/31323]: Append to metadata: " fields := struct {
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834250 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834256 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834263 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _intfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834268 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834273 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834279 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 16; } _intfield2;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834284 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834289 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834294 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 1; encoding = none; base = 10; } _longfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834312 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834317 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834325 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; byte_order = be; } _netintfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834330 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834335 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834341 [31312/31323]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 16; byte_order = be; } _netintfieldhex;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834346 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834351 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834357 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 1; encoding = none; base = 10; } _arrfield1[3];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834362 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834367 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834373 [31312/31323]: Append to metadata: "integer { size = 8; align = 8; signed = 1; encoding = UTF8; base = 10; } _arrfield2[10];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834379 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834383 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834390 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 0; encoding = none; base = 10; } __seqfield1_length;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834395 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834400 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834407 [31312/31323]: Append to metadata: "integer { size = 8; align = 8; signed = 1; encoding = none; base = 10; } _seqfield1[ __seqfield1_length ];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834412 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834417 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834423 [31312/31323]: Append to metadata: "integer { size = 64; align = 8; signed = 0; encoding = none; base = 10; } __seqfield2_length;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834428 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834432 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834439 [31312/31323]: Append to metadata: "integer { size = 8; align = 8; signed = 1; encoding = UTF8; base = 10; } _seqfield2[ __seqfield2_length ];
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834444 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834449 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834454 [31312/31323]: Append to metadata: "string _stringfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834459 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834469 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834475 [31312/31323]: Append to metadata: "floating_point { exp_dig = 8; mant_dig = 24; align = 8; } _floatfield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834481 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834486 [31312/31323]: Append to metadata: " " (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834491 [31312/31323]: Append to metadata: "floating_point { exp_dig = 11; mant_dig = 53; align = 8; } _doublefield;
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834497 [31312/31323]: Append to metadata: " };
};
" (in lttng_metadata_printf() at ust-metadata.c:179)
DEBUG3 - 12:54:41.834505 [31312/31323]: UST registry event tp:tptest with id 0 added successfully (in add_event_ust_registry() at ust-app.c:5523)
DEBUG3 - 12:54:41.834511 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG1 - 12:54:41.835295 [31312/31320]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1896)
DEBUG1 - 12:54:41.835309 [31312/31320]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
DEBUG1 - 12:54:41.835315 [31312/31320]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
DEBUG1 - 12:54:41.835320 [31312/31320]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1896)
DEBUG1 - 12:54:41.835322 [31312/31322]: Apps thread return from poll on 2 fds (in thread_manage_apps() at main.c:1592)
DEBUG1 - 12:54:41.835350 [31312/31322]: Apps with sock 32 added to poll set (in thread_manage_apps() at main.c:1649)
DEBUG1 - 12:54:41.835357 [31312/31322]: Apps thread polling (in thread_manage_apps() at main.c:1585)
DEBUG3 - 12:54:41.835716 [31312/31323]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
DEBUG3 - 12:54:41.835731 [31312/31323]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5629)
DEBUG3 - 12:54:41.835740 [31312/31323]: UST app recv notify failed. Application died (in ust_app_recv_notify() at ust-app.c:5636)
DEBUG1 - 12:54:41.835748 [31312/31323]: UST app notify socket unregister 37 (in ust_app_notify_sock_unregister() at ust-app.c:5786)
DEBUG3 - 12:54:41.835762 [31312/31323]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
DEBUG1 - 12:54:41.835803 [31312/31322]: Apps thread return from poll on 3 fds (in thread_manage_apps() at main.c:1592)
DEBUG1 - 12:54:41.835829 [31312/31322]: PID 31341 unregistering with sock 32 (in ust_app_unregister() at ust-app.c:3438)
DEBUG3 - 12:54:41.835865 [31312/31322]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG2 - 12:54:41.835885 [31312/31322]: Consumer push metadata to consumer socket 35 (in consumer_push_metadata() at consumer.c:1308)
DEBUG1 - 12:54:41.835935 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:41.835972 [31329/31338]: UST consumer push metadata key 2 of len 3724 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1638)
DEBUG3 - 12:54:41.839134 [31312/31322]: Consumer pushing metadata on sock 35 of len 3724 (in consumer_push_metadata() at consumer.c:1326)
DEBUG1 - 12:54:41.839228 [31329/31338]: UST consumer push metadata key 2 of len 3724 (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1237)
DEBUG1 - 12:54:41.839271 [31329/31338]: Writing 3724 bytes from offset 0 in metadata cache (in consumer_metadata_cache_write() at consumer-metadata-cache.c:134)
DEBUG1 - 12:54:41.839291 [31329/31338]: Waiting for metadata to be flushed (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1278)
DEBUG1 - 12:54:41.839307 [31329/31336]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:41.839324 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:41.839332 [31329/31336]: Metadata available on fd 40 (in consumer_thread_metadata_poll() at consumer.c:2364)
DEBUG1 - 12:54:41.839338 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:41.839372 [31329/31336]: Relayd sending metadata of size 3773 (in relayd_send_metadata() at relayd.c:459)
DEBUG1 - 12:54:41.839419 [31329/31336]: Metadata stream id 3 with padding 335 written before data (in write_relayd_metadata_id() at consumer.c:1484)
DEBUG1 - 12:54:41.839431 [31329/31336]: Consumer mmap write() ret 3761 (len 3761) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:41.839441 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:41.839449 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG1 - 12:54:41.844886 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:41.844930 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:41.844965 [31312/31319]: Processing client command 17 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:41.844975 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:41.844982 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:41.844990 [31312/31319]: Stopping all UST traces (in ust_app_stop_trace_all() at ust-app.c:4894)
DEBUG1 - 12:54:41.844997 [31312/31319]: Stopping tracing for ust app pid 31341 (in ust_app_stop_trace() at ust-app.c:4432)
DEBUG1 - 12:54:41.845005 [31312/31319]: Flushing session buffers for all ust apps (in ust_app_flush_session() at ust-app.c:4589)
DEBUG2 - 12:54:41.845013 [31312/31319]: Consumer flush channel key 1 (in consumer_flush_channel() at consumer.c:1174)
DEBUG1 - 12:54:42.394608 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.395640 [31312/31322]: Apps thread polling (in thread_manage_apps() at main.c:1585)
DEBUG1 - 12:54:42.395941 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.396221 [31329/31338]: UST consumer flush channel key 1 (in flush_channel() at ust-consumer.c:751)
DEBUG1 - 12:54:42.396719 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.396794 [31329/31337]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.396974 [31329/31337]: Normal read on fd 32 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG3 - 12:54:42.396971 [31312/31319]: No metadata to push for metadata key 2 (in ust_app_push_metadata() at ust-app.c:575)
DEBUG1 - 12:54:42.397051 [31329/31337]: In UST read_subbuffer (wait_fd: 32, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.397178 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.397447 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.397525 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.397877 [31329/31337]: Consumer mmap write() ret 84 (len 84) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:42.398155 [31329/31337]: Sending metadata request to sessiond, session id 0, per-pid 1, app UID 0 and channek key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2824)
DEBUG1 - 12:54:42.398988 [31312/31330]: Metadata request received for session 0, key 2 (in ust_consumer_metadata_request() at ust-consumer.c:484)
DEBUG3 - 12:54:42.399327 [31312/31330]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:42.399480 [31312/31330]: No metadata to push for metadata key 2 (in ust_app_push_metadata() at ust-app.c:575)
DEBUG1 - 12:54:42.399566 [31312/31330]: No metadata to push (in ust_app_push_metadata() at ust-app.c:578)
DEBUG2 - 12:54:42.399617 [31312/31330]: Consumer push metadata to consumer socket 36 (in consumer_push_metadata() at consumer.c:1308)
DEBUG1 - 12:54:42.399916 [31329/31337]: No new metadata to receive for key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2874)
DEBUG1 - 12:54:42.400081 [31329/31337]: Relayd sending index for stream ID 1 (in relayd_send_index() at relayd.c:839)
DEBUG1 - 12:54:42.400442 [31312/31330]: UST Consumer metadata pushed successfully (in ust_consumer_metadata_request() at ust-consumer.c:523)
DEBUG1 - 12:54:42.402810 [31329/31337]: Normal read on fd 34 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG1 - 12:54:42.402956 [31329/31337]: In UST read_subbuffer (wait_fd: 34, name: channel0_1) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.403620 [31329/31337]: Consumer mmap write() ret 10393 (len 10393) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:42.403755 [31329/31337]: Sending metadata request to sessiond, session id 0, per-pid 1, app UID 0 and channek key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2824)
DEBUG1 - 12:54:42.404015 [31312/31330]: Metadata request received for session 0, key 2 (in ust_consumer_metadata_request() at ust-consumer.c:484)
DEBUG3 - 12:54:42.404118 [31312/31330]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:42.404191 [31312/31330]: No metadata to push for metadata key 2 (in ust_app_push_metadata() at ust-app.c:575)
DEBUG1 - 12:54:42.404236 [31312/31330]: No metadata to push (in ust_app_push_metadata() at ust-app.c:578)
DEBUG2 - 12:54:42.404279 [31312/31330]: Consumer push metadata to consumer socket 36 (in consumer_push_metadata() at consumer.c:1308)
DEBUG1 - 12:54:42.404499 [31329/31337]: No new metadata to receive for key 2 (in lttng_ustconsumer_request_metadata() at ust-consumer.c:2874)
DEBUG1 - 12:54:42.404627 [31329/31337]: Relayd sending index for stream ID 2 (in relayd_send_index() at relayd.c:839)
DEBUG1 - 12:54:42.404915 [31312/31330]: UST Consumer metadata pushed successfully (in ust_consumer_metadata_request() at ust-consumer.c:523)
DEBUG1 - 12:54:42.407127 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:42.416927 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.417230 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.417627 [31312/31319]: Processing client command 24 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.417721 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.417780 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.417855 [31312/31319]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1118)
DEBUG1 - 12:54:42.418180 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.418383 [31329/31338]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1381)
DEBUG1 - 12:54:42.418453 [31329/31338]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3601)
DEBUG1 - 12:54:42.418532 [31329/31338]: Relayd begin data pending (in relayd_begin_data_pending() at relayd.c:738)
DEBUG1 - 12:54:42.419914 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.420024 [31329/31338]: Relayd data pending for stream id 1 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.420955 [31329/31338]: Relayd data is NOT pending for stream id 1 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.421068 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.421127 [31329/31338]: Relayd data pending for stream id 2 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.421821 [31329/31338]: Relayd data is NOT pending for stream id 2 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.421916 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.421966 [31329/31338]: UST consumer metadata pending check: contiguous 3724 vs pushed 3724 (in lttng_ustconsumer_data_pending() at ust-consumer.c:2664)
DEBUG1 - 12:54:42.422024 [31329/31338]: Relayd checking quiescent control state (in relayd_quiescent_control() at relayd.c:693)
DEBUG1 - 12:54:42.422830 [31329/31338]: Relayd end data pending (in relayd_end_data_pending() at relayd.c:786)
DEBUG1 - 12:54:42.423723 [31329/31338]: Relayd end data pending is data inflight: 0 (in relayd_end_data_pending() at relayd.c:811)
DEBUG1 - 12:54:42.423872 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.424032 [31312/31319]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1154)
DEBUG1 - 12:54:42.424177 [31312/31319]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.424344 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.424412 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.424924 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.425127 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.425419 [31312/31319]: Processing client command 11 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.425506 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.425562 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.425628 [31312/31319]: Listing domains found UST global domain (in cmd_list_domains() at cmd.c:2851)
DEBUG1 - 12:54:42.425743 [31312/31319]: Sending response (size: 328, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.425866 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.425923 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.426404 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.426578 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.426840 [31312/31319]: Processing client command 10 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.426918 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.426971 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.427059 [31312/31319]: Consumer socket created (fd: 35) and added to output (in consumer_create_socket() at consumer.c:301)
DEBUG1 - 12:54:42.427125 [31312/31319]: Setting relayd for session trace (in cmd_setup_relayd() at cmd.c:1014)
DEBUG3 - 12:54:42.427213 [31312/31319]: Number of UST global channels 1 (in cmd_list_channels() at cmd.c:2934)
DEBUG1 - 12:54:42.427280 [31312/31319]: Listing channels for session trace (in list_lttng_channels() at cmd.c:245)
DEBUG3 - 12:54:42.427373 [31312/31319]: Consumer discarded events id 0 (in consumer_get_discarded_events() at consumer.c:1428)
DEBUG1 - 12:54:42.427683 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.427873 [31329/31338]: UST consumer discarded events command for session id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1747)
DEBUG1 - 12:54:42.427969 [31329/31338]: UST consumer discarded events command for session id 0, channel key 1 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1774)
DEBUG1 - 12:54:42.428049 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.428177 [31312/31319]: Consumer discarded 0 events in session id 0 (in consumer_get_discarded_events() at consumer.c:1465)
DEBUG1 - 12:54:42.428348 [31312/31319]: Sending response (size: 660, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.428483 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.428540 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.521311 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.521686 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.522088 [31312/31319]: Processing client command 13 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.522192 [31312/31319]: Counting number of available session for UID 0 GID 0 (in lttng_sessions_count() at main.c:2954)
DEBUG1 - 12:54:42.522332 [31312/31319]: Getting all available session for UID 0 GID 0 (in cmd_list_lttng_sessions() at cmd.c:3049)
DEBUG1 - 12:54:42.522518 [31312/31319]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.522724 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.522790 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.523330 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.523534 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.523811 [31312/31319]: Processing client command 17 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.523906 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.523964 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:42.524038 [31312/31319]: Sending response (size: 20, retcode: Tracing has already been stopped (81)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.524158 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.524218 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.524563 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.524712 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.524969 [31312/31319]: Processing client command 24 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.525049 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.525104 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.525169 [31312/31319]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1118)
DEBUG1 - 12:54:42.525414 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.525849 [31329/31338]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1381)
DEBUG1 - 12:54:42.525944 [31329/31338]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3601)
DEBUG1 - 12:54:42.526028 [31329/31338]: Relayd begin data pending (in relayd_begin_data_pending() at relayd.c:738)
DEBUG1 - 12:54:42.527667 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.527787 [31329/31338]: Relayd data pending for stream id 1 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.528588 [31329/31338]: Relayd data is NOT pending for stream id 1 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.528697 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.528875 [31329/31338]: Relayd data pending for stream id 2 (in relayd_data_pending() at relayd.c:644)
DEBUG1 - 12:54:42.529536 [31329/31338]: Relayd data is NOT pending for stream id 2 (in relayd_data_pending() at relayd.c:674)
DEBUG1 - 12:54:42.529627 [31329/31338]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2639)
DEBUG1 - 12:54:42.529674 [31329/31338]: UST consumer metadata pending check: contiguous 3724 vs pushed 3724 (in lttng_ustconsumer_data_pending() at ust-consumer.c:2664)
DEBUG1 - 12:54:42.529727 [31329/31338]: Relayd checking quiescent control state (in relayd_quiescent_control() at relayd.c:693)
DEBUG1 - 12:54:42.530416 [31329/31338]: Relayd end data pending (in relayd_end_data_pending() at relayd.c:786)
DEBUG1 - 12:54:42.531372 [31329/31338]: Relayd end data pending is data inflight: 0 (in relayd_end_data_pending() at relayd.c:811)
DEBUG1 - 12:54:42.531518 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.531665 [31312/31319]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1154)
DEBUG1 - 12:54:42.531801 [31312/31319]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.531945 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.532003 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.532446 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.532636 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.532915 [31312/31319]: Processing client command 17 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.533000 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.533054 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG1 - 12:54:42.533121 [31312/31319]: Sending response (size: 20, retcode: Tracing has already been stopped (81)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.533230 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.533285 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.533594 [31312/31319]: Wait for client response (in thread_manage_clients() at main.c:4449)
DEBUG1 - 12:54:42.533741 [31312/31319]: Receiving data from client ... (in thread_manage_clients() at main.c:4494)
DEBUG1 - 12:54:42.533974 [31312/31319]: Processing client command 9 (in process_client_msg() at main.c:2985)
DEBUG1 - 12:54:42.534054 [31312/31319]: Getting session trace by name (in process_client_msg() at main.c:3074)
DEBUG2 - 12:54:42.534105 [31312/31319]: Trying to find session by name trace (in session_find_by_name() at session.c:276)
DEBUG3 - 12:54:42.534170 [31312/31319]: No kernel session when tearing down session (in kernel_destroy_session() at kernel.c:897)
DEBUG2 - 12:54:42.534246 [31312/31319]: Sending destroy relayd command to consumer sock 35 (in consumer_send_destroy_relayd() at consumer.c:208)
DEBUG1 - 12:54:42.534438 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.534609 [31329/31338]: UST consumer destroying relayd 2 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1346)
DEBUG1 - 12:54:42.534790 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG2 - 12:54:42.534911 [31312/31319]: Consumer send destroy relayd command done (in consumer_send_destroy_relayd() at consumer.c:223)
DEBUG1 - 12:54:42.535004 [31312/31319]: Destroy all UST traces (in ust_app_destroy_trace_all() at ust-app.c:4922)
DEBUG2 - 12:54:42.535069 [31312/31319]: Trace UST destroy session 0 (in trace_ust_destroy_session() at trace-ust.c:1159)
DEBUG3 - 12:54:42.535476 [31312/31319]: Buffer registry per UID destroy with id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_destroy() at buffer-registry.c:678)
DEBUG2 - 12:54:42.535577 [31312/31319]: Consumer close metadata channel key 2 (in consumer_close_metadata() at consumer.c:1240)
DEBUG1 - 12:54:42.535810 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.535986 [31329/31338]: UST consumer close metadata key 2 (in close_metadata() at ust-consumer.c:835)
DEBUG3 - 12:54:42.535941 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.536069 [31329/31338]: Closing metadata channel key 2 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2705)
DEBUG1 - 12:54:42.536320 [31329/31338]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3194)
DEBUG1 - 12:54:42.536425 [31329/31336]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:42.536486 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:42.536545 [31329/31336]: Metadata fd 40 is hup|err. (in consumer_thread_metadata_poll() at consumer.c:2386)
DEBUG1 - 12:54:42.536593 [31329/31336]: Attempting to flush and consume the UST buffers (in consumer_thread_metadata_poll() at consumer.c:2390)
DEBUG1 - 12:54:42.536824 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.536932 [31329/31336]: Relayd sending metadata of size 49 (in relayd_send_metadata() at relayd.c:459)
DEBUG1 - 12:54:42.537223 [31329/31336]: Metadata stream id 3 with padding 4059 written before data (in write_relayd_metadata_id() at consumer.c:1484)
DEBUG1 - 12:54:42.537307 [31329/31336]: Consumer mmap write() ret 37 (len 37) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1656)
DEBUG1 - 12:54:42.537387 [31329/31336]: In UST read_subbuffer (wait_fd: 40, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.537526 [31329/31336]: Closing metadata channel key 2 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2705)
DEBUG1 - 12:54:42.537656 [31329/31336]: Relayd closing stream id 3 (in relayd_send_close_stream() at relayd.c:594)
DEBUG1 - 12:54:42.538253 [31312/31319]: Destroying session trace (in session_destroy() at session.c:331)
DEBUG1 - 12:54:42.538417 [31312/31319]: Empty ltt_sessions_ht_by_id, destroying it (in del_session_ht() at session.c:240)
DEBUG1 - 12:54:42.538553 [31312/31319]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4544)
DEBUG1 - 12:54:42.538693 [31312/31319]: Clean command context structure (in clean_command_ctx() at main.c:784)
DEBUG1 - 12:54:42.538748 [31312/31319]: Accepting client command ... (in thread_manage_clients() at main.c:4397)
DEBUG1 - 12:54:42.538896 [31312/31325]: Thread kernel return from poll on 2 fds (in thread_manage_kernel() at main.c:1105)
DEBUG1 - 12:54:42.539163 [31312/31325]: Updating kernel poll set (in update_kernel_poll() at main.c:888)
DEBUG1 - 12:54:42.539230 [31312/31325]: Thread kernel polling (in thread_manage_kernel() at main.c:1098)
DEBUG3 - 12:54:42.637932 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.638202 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.740765 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.741037 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.842380 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.842639 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.921328 [31329/31336]: Relayd close stream id 3 successfully (in relayd_send_close_stream() at relayd.c:623)
DEBUG1 - 12:54:42.921639 [31329/31336]: Consumer delete channel key 2 (in consumer_del_channel() at consumer.c:360)
DEBUG1 - 12:54:42.922532 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG3 - 12:54:42.943929 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.944180 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.104595 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.104621 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.114787 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.114812 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.119931 [31329/31348]: Destroying metadata cache (in consumer_metadata_cache_destroy() at consumer-metadata-cache.c:220)
DEBUG3 - 12:54:42.119951 [31312/31344]: Call RCU deleting app PID 31341 (in delete_ust_app_rcu() at ust-app.c:940)
libringbuffer[31329/31348]: ring buffer relay-metadata-mmap: 0 records written, 0 records overrun
(in lib_ring_buffer_print_errors() at ring_buffer_frontend.c:1647)
DEBUG3 - 12:54:42.119989 [31312/31344]: Buffer registry per UID find id: 0, ABI: 64, uid: 0 (in buffer_reg_uid_find() at buffer-registry.c:203)
DEBUG3 - 12:54:42.120016 [31312/31344]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:457)
DEBUG2 - 12:54:42.120061 [31312/31344]: UST app pid 31341 deleted (in delete_ust_app() at ust-app.c:924)
DEBUG2 - 12:54:42.120070 [31312/31344]: Trace destroy UST event tp:tptest (in trace_ust_destroy_event() at trace-ust.c:1003)
DEBUG2 - 12:54:42.120076 [31312/31344]: Trace destroy UST channel channel0 (in _trace_ust_destroy_channel() at trace-ust.c:1068)
DEBUG3 - 12:54:42.120083 [31312/31344]: Buffer registry session destroy (in buffer_reg_session_destroy() at buffer-registry.c:597)
DEBUG3 - 12:54:42.120090 [31312/31344]: Buffer registry channel destroy with key 0 (in buffer_reg_channel_destroy() at buffer-registry.c:552)
DEBUG3 - 12:54:42.120095 [31312/31344]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
DEBUG3 - 12:54:42.120102 [31312/31344]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
DEBUG1 - 12:54:42.120146 [31329/31335]: Channel poll return from wait with 2 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:42.120164 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:42.120173 [31329/31335]: Channel fd 29 is hup|err. (in consumer_thread_channel_poll() at consumer.c:2999)
DEBUG1 - 12:54:42.120199 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:42.120214 [31329/31337]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.120221 [31329/31337]: fd 32 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2657)
DEBUG1 - 12:54:42.120227 [31329/31337]: Polling fd 32 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120232 [31329/31337]: fd 34 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2657)
DEBUG1 - 12:54:42.120247 [31329/31337]: Polling fd 34 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120252 [31329/31337]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:42.120259 [31329/31337]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.120264 [31329/31337]: Normal read on fd 32 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG1 - 12:54:42.120269 [31329/31337]: In UST read_subbuffer (wait_fd: 32, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.120276 [31329/31337]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2468)
DEBUG1 - 12:54:42.120282 [31329/31337]: Normal read on fd 34 (in consumer_thread_data_poll() at consumer.c:2632)
DEBUG1 - 12:54:42.120287 [31329/31337]: In UST read_subbuffer (wait_fd: 34, name: channel0_1) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2417)
DEBUG1 - 12:54:42.120292 [31329/31337]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2468)
DEBUG1 - 12:54:42.120297 [31329/31337]: Polling fd 32 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120307 [31329/31337]: Consumer stream destroy monitored key: 32 (in destroy_close_stream() at consumer-stream.c:265)
DEBUG1 - 12:54:42.120323 [31329/31337]: Relayd closing stream id 1 (in relayd_send_close_stream() at relayd.c:594)
DEBUG1 - 12:54:42.120530 [31329/31337]: Relayd close stream id 1 successfully (in relayd_send_close_stream() at relayd.c:623)
DEBUG1 - 12:54:42.120555 [31329/31337]: Polling fd 34 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2668)
DEBUG1 - 12:54:42.120592 [31329/31337]: Consumer stream destroy monitored key: 34 (in destroy_close_stream() at consumer-stream.c:265)
DEBUG1 - 12:54:42.120611 [31329/31337]: Relayd closing stream id 2 (in relayd_send_close_stream() at relayd.c:594)
DEBUG1 - 12:54:42.120754 [31329/31337]: Relayd close stream id 2 successfully (in relayd_send_close_stream() at relayd.c:623)
DEBUG1 - 12:54:42.120769 [31329/31337]: Consumer destroy and close relayd socket pair (in consumer_destroy_relayd() at consumer.c:338)
DEBUG1 - 12:54:42.120779 [31329/31337]: Consumer delete channel key 1 (in consumer_del_channel() at consumer.c:360)
DEBUG1 - 12:54:42.123937 [31329/31337]: Updating poll fd array (in update_poll_array() at consumer.c:1085)
DEBUG1 - 12:54:42.123949 [31329/31337]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2527)
DEBUG1 - 12:54:42.123932 [31329/31334]: Signal timer metadata thread teardown (in consumer_timer_thread() at consumer-timer.c:594)
DEBUG3 - 12:54:42.124982 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.125006 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.135182 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.135209 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.145386 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.145413 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
libringbuffer[31329/31348]: ring buffer relay-discard-mmap, cpu 0: 0 records written, 0 records overrun
(in lib_ring_buffer_print_errors() at ring_buffer_frontend.c:1653)
libringbuffer[31329/31348]: ring buffer relay-discard-mmap, cpu 1: 0 records written, 0 records overrun
(in lib_ring_buffer_print_errors() at ring_buffer_frontend.c:1653)
DEBUG3 - 12:54:42.155595 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.155631 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG3 - 12:54:42.165823 [31312/31314]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
DEBUG3 - 12:54:42.165848 [31312/31314]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
DEBUG1 - 12:54:42.174367 [31329/31338]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3178)
DEBUG1 - 12:54:42.174396 [31329/31338]: Consumer received unexpected message size 0 (expects 12668) (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1309)
DEBUG1 - 12:54:42.174404 [31329/31338]: Communication interrupted on command socket (in consumer_thread_sessiond_poll() at consumer.c:3185)
DEBUG1 - 12:54:42.174409 [31329/31338]: Consumer thread sessiond poll exiting (in consumer_thread_sessiond_poll() at consumer.c:3200)
DEBUG1 - 12:54:42.174414 [31329/31338]: UST consumer closing all metadata streams (in lttng_ustconsumer_close_all_metadata() at ust-consumer.c:2748)
DEBUG1 - 12:54:42.174547 [31329/31335]: Channel poll return from wait with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:42.174562 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:42.174574 [31329/31335]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2849)
DEBUG1 - 12:54:42.174579 [31329/31335]: Channel poll return from wait with 0 fd(s) (in consumer_thread_channel_poll() at consumer.c:2853)
DEBUG1 - 12:54:42.174584 [31329/31335]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2855)
DEBUG1 - 12:54:42.174617 [31329/31333]: Health check thread dying (in thread_manage_health() at health-consumerd.c:342)
DEBUG1 - 12:54:42.174704 [31329/31337]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2531)
DEBUG1 - 12:54:42.174728 [31329/31337]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2555)
DEBUG1 - 12:54:42.174739 [31329/31337]: Consumer delete flagged data stream (in validate_endpoint_status_data_stream() at consumer.c:2175)
DEBUG1 - 12:54:42.174746 [31329/31337]: polling thread exiting (in consumer_thread_data_poll() at consumer.c:2697)
DEBUG1 - 12:54:42.174772 [31329/31336]: Metadata poll return from wait with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:42.174798 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:42.174804 [31329/31336]: Metadata thread pipe hung up (in consumer_thread_metadata_poll() at consumer.c:2332)
DEBUG1 - 12:54:42.174818 [31329/31336]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2267)
DEBUG1 - 12:54:42.174824 [31329/31336]: Metadata poll return from wait with 0 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2270)
DEBUG1 - 12:54:42.174829 [31329/31336]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2272)
DEBUG1 - 12:54:42.174833 [31329/31336]: Metadata poll thread exiting (in consumer_thread_metadata_poll() at consumer.c:2426)
DEBUG1 - 12:54:42.184797 [31329/31335]: Channel poll thread exiting (in consumer_thread_channel_poll() at consumer.c:3036)
DEBUG1 - 12:54:42.264806 [31329/31329]: Consumer destroying it. Closing everything. (in lttng_consumer_destroy() at consumer.c:1425)
DEBUG1 - 12:54:42.331939 [31329/31329]: Destroying run_as worker (in run_as_destroy_worker() at runas.c:714)
DEBUG1 - 12:54:42.331956 [31329/31329]: Closing run_as worker socket (in run_as_destroy_worker() at runas.c:720)
DEBUG1 - 12:54:42.332015 [31332/31332]: run_as worker exiting (ret = 0) (in run_as_create_worker() at runas.c:664)
libust[31332/31332]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at lttng-ring-buffer-client.h:831)
libust[31332/31332]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at lttng-ring-buffer-metadata-client.h:356)
DEBUG1 - 12:54:42.332409 [31329/31329]: lttng-runas terminated with status code 0 (in run_as_destroy_worker() at runas.c:742)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at lttng-ring-buffer-client.h:831)
libust[31329/31329]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at lttng-ring-buffer-metadata-client.h:356)
DEBUG1 - 12:54:42.332830 [31313/31313]: run_as worker exiting (ret = 0) (in run_as_create_worker() at runas.c:664)
libust[31313/31313]: LTT : ltt ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at lttng-ring-buffer-client.h:831)
libust[31313/31313]: LTT : ltt ring buffer client "relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at lttng-ring-buffer-metadata-client.h:356)
Basic setup:
0: ['make', 'V=1'] 1: ['lttng', 'create', '--set-url=net://localhost:38120:42335', 'trace', '--live'] 2: ['lttng', 'enable-event', '-u', 'tp:tptest'] 3: ['lttng', 'start'] 4: ['./app', '100'] 5: ['lttng', 'stop'] 6: ['lttng', 'destroy', '-a']
Current code generating the test case can be found here : https://github.com/lttng/lttng-ivc/blob/master/lttng_ivc/tests/babeltrace/live/test_babeltrace_live.py
No data to display
Actions