Project

General

Profile

Bug #1213 » log.txt

lttng-sessiond's log - jinming liao, 01/14/2020 07:02 AM

 
1
DEBUG1 - 16:17:36.106565048 [17803/17803]: [sessiond configuration]
2
DEBUG1 - 16:17:36.106600875 [17803/17803]: 	verbose:                      3
3
DEBUG1 - 16:17:36.106603911 [17803/17803]: 	verbose consumer:             1
4
DEBUG1 - 16:17:36.106606440 [17803/17803]: 	quiet mode:                   False
5
DEBUG1 - 16:17:36.106608669 [17803/17803]: 	agent_tcp_port:               [5345, 5354]
6
DEBUG1 - 16:17:36.106611008 [17803/17803]: 	application socket timeout:   5
7
DEBUG1 - 16:17:36.106613259 [17803/17803]: 	no-kernel:                    True
8
DEBUG1 - 16:17:36.106615469 [17803/17803]: 	background:                   False
9
DEBUG1 - 16:17:36.106617939 [17803/17803]: 	daemonize:                    False
10
DEBUG1 - 16:17:36.106620468 [17803/17803]: 	signal parent on start:       False
11
DEBUG1 - 16:17:36.106623378 [17803/17803]: 	tracing group name:           tracing
12
DEBUG1 - 16:17:36.106626408 [17803/17803]: 	kmod_probe_list:              None
13
DEBUG1 - 16:17:36.106629568 [17803/17803]: 	kmod_extra_probe_list:        None
14
DEBUG1 - 16:17:36.106631705 [17803/17803]: 	rundir:                       /var/lib/log/lttng_home/.lttng
15
DEBUG1 - 16:17:36.106633996 [17803/17803]: 	application socket path:      /var/lib/log/lttng_home/.lttng/lttng-ust-sock-7
16
DEBUG1 - 16:17:36.106636270 [17803/17803]: 	client socket path:           /var/lib/log/lttng_home/.lttng/client-lttng-sessiond
17
DEBUG1 - 16:17:36.106638523 [17803/17803]: 	wait shm path:                /lttng-ust-wait-7-1000
18
DEBUG1 - 16:17:36.106640649 [17803/17803]: 	health socket path:           /var/lib/log/lttng_home/.lttng/sessiond-health
19
DEBUG1 - 16:17:36.106642832 [17803/17803]: 	LTTNG_UST_CLOCK_PLUGIN:       None
20
DEBUG1 - 16:17:36.106644893 [17803/17803]: 	pid file path:                /var/lib/log/lttng_home/.lttng/lttng-sessiond.pid
21
DEBUG1 - 16:17:36.106647107 [17803/17803]: 	lock file path:               /var/lib/log/lttng_home/.lttng/lttng-sessiond.lck
22
DEBUG1 - 16:17:36.106649252 [17803/17803]: 	session load path:            None
23
DEBUG1 - 16:17:36.106652274 [17803/17803]: 	agent port file path:         /var/lib/log/lttng_home/.lttng/agent.port
24
DEBUG3 - 16:17:36.106654576 [17803/17803]: Creating LTTng run directory: /var/lib/log/lttng_home/.lttng (in create_lttng_rundir() at main.c:5264)
25
DEBUG1 - 16:17:36.106995551 [17805/17805]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:536)
26
DEBUG1 - 16:17:36.107088291 [17805/17805]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:597)
27
DEBUG1 - 16:17:36.107136383 [17803/17803]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
28
DEBUG1 - 16:17:36.107192152 [17803/17806]: [ht-thread] startup. (in thread_ht_cleanup() at ht-cleanup.c:101)
29
DEBUG1 - 16:17:36.107222613 [17803/17806]: epoll set max size is 74124963 (in compat_epoll_set_max_size() at compat-epoll.c:337)
30
DEBUG3 - 16:17:36.107238395 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
31
DEBUG3 - 16:17:36.110542019 [17803/17803]: Created hashtable size 4 at 0x127e890 of type 1 (in lttng_ht_new() at hashtable.c:145)
32
DEBUG3 - 16:17:36.110550796 [17803/17803]: Created hashtable size 4 at 0x127edf0 of type 1 (in lttng_ht_new() at hashtable.c:145)
33
DEBUG3 - 16:17:36.110554308 [17803/17803]: Created hashtable size 4 at 0x127f330 of type 1 (in lttng_ht_new() at hashtable.c:145)
34
DEBUG3 - 16:17:36.110560263 [17803/17803]: Created hashtable size 4 at 0x127f870 of type 1 (in lttng_ht_new() at hashtable.c:145)
35
DEBUG2 - 16:17:36.110567134 [17803/17803]: Creating consumer directory: /var/lib/log/lttng_home/.lttng/ustconsumerd64 (in set_consumer_sockets() at main.c:5306)
36
DEBUG2 - 16:17:36.110620726 [17803/17803]: Creating consumer directory: /var/lib/log/lttng_home/.lttng/ustconsumerd32 (in set_consumer_sockets() at main.c:5306)
37
DEBUG3 - 16:17:36.110686428 [17803/17803]: Session daemon client socket 18 and application socket 19 created (in init_daemon_socket() at main.c:5133)
38
DEBUG3 - 16:17:36.110702184 [17803/17803]: Created hashtable size 4 at 0x127fdb0 of type 2 (in lttng_ht_new() at hashtable.c:145)
39
DEBUG3 - 16:17:36.110709204 [17803/17803]: Global buffer per UID registry initialized (in buffer_reg_init_uid_registry() at buffer-registry.c:99)
40
DEBUG3 - 16:17:36.110714406 [17803/17803]: Created hashtable size 4 at 0x12802f0 of type 2 (in lttng_ht_new() at hashtable.c:145)
41
DEBUG3 - 16:17:36.110716809 [17803/17803]: Global buffer per PID registry initialized (in buffer_reg_init_pid_registry() at buffer-registry.c:228)
42
DEBUG1 - 16:17:36.110721788 [17803/17803]: Command subsystem initialized (in cmd_init() at cmd.c:4149)
43
DEBUG1 - 16:17:36.110799593 [17803/17803]: Pid 17803 written in file /var/lib/log/lttng_home/.lttng/lttng-sessiond.pid (in utils_create_pid_file() at utils.c:507)
44
DEBUG1 - 16:17:36.110822279 [17803/17803]: TCP inet operation timeout set to 180 sec (in lttcomm_inet_init() at inet.c:546)
45
DEBUG1 - 16:17:36.110855753 [17803/17808]: [thread] Manage health check started (in thread_manage_health() at main.c:4070)
46
DEBUG1 - 16:17:36.110909907 [17803/17808]: Health check ready (in thread_manage_health() at main.c:4132)
47
DEBUG1 - 16:17:36.110923318 [17803/17810]: [thread] Manage client started (in thread_manage_clients() at main.c:4261)
48
DEBUG1 - 16:17:36.110954171 [17803/17811]: [thread] Dispatch UST command started (in thread_dispatch_ust_registration() at main.c:1757)
49
DEBUG1 - 16:17:36.110946836 [17803/17812]: [thread] Manage application registration started (in thread_registration_apps() at main.c:2002)
50
DEBUG1 - 16:17:36.110929096 [17803/17809]: [notification-thread] Started notification thread (in thread_notification() at notification-thread.c:482)
51
DEBUG1 - 16:17:36.110959609 [17803/17813]: [thread] Manage application started (in thread_manage_apps() at main.c:1443)
52
DEBUG1 - 16:17:36.111059553 [17803/17812]: Notifying applications of session daemon state: 1 (in notify_ust_apps() at main.c:661)
53
DEBUG1 - 16:17:36.111062674 [17803/17809]: [notification-thread] Creating notification channel UNIX socket at /var/lib/log/lttng_home/.lttng/sessiond-notification (in notification_channel_socket_create() at notification-thread.c:221)
54
DEBUG1 - 16:17:36.110994498 [17803/17811]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
55
DEBUG1 - 16:17:36.111003021 [17803/17814]: [ust-thread] Manage application notify command (in ust_thread_manage_notify() at ust-thread.c:40)
56
DEBUG1 - 16:17:36.111081161 [17803/17816]: [load-session-thread] Load session (in thread_load_session() at load-session-thread.c:91)
57
DEBUG1 - 16:17:36.111072042 [17803/17811]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
58
DEBUG3 - 16:17:36.111094862 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
59
DEBUG1 - 16:17:36.111072233 [17803/17813]: Apps thread polling (in thread_manage_apps() at main.c:1473)
60
DEBUG1 - 16:17:36.111104619 [17803/17809]: [notification-thread] Notification channel UNIX socket created (fd = 31) (in notification_channel_socket_create() at notification-thread.c:248)
61
DEBUG1 - 16:17:36.111028802 [17803/17815]: [agent-thread] Manage agent application registration. (in agent_thread_manage_registration() at agent-thread.c:300)
62
DEBUG1 - 16:17:36.111117958 [17803/17812]: Got the wait shm fd 33 (in get_wait_shm() at shm.c:115)
63
DEBUG3 - 16:17:36.111128288 [17803/17815]: URI string: tcp://localhost (in uri_parse() at uri.c:324)
64
DEBUG1 - 16:17:36.111119488 [17803/17809]: [notification-thread] Listening on notification channel socket (in init_thread_state() at notification-thread.c:387)
65
DEBUG1 - 16:17:36.111149792 [17803/17812]: Futex wait update active 1 (in futex_wait_update() at futex.c:65)
66
DEBUG1 - 16:17:36.111153200 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
67
DEBUG1 - 16:17:36.111158230 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
68
DEBUG1 - 16:17:39.312718795 [17803/17812]: UST registration received with pid:17436 ppid:16398 uid:1000 gid:1000 sock:33 name:hello-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
69
DEBUG1 - 16:17:39.312737333 [17803/17812]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
70
DEBUG1 - 16:17:39.312740751 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
71
DEBUG1 - 16:17:39.312742191 [17803/17811]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
72
DEBUG1 - 16:17:39.312751241 [17803/17811]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
73
DEBUG1 - 16:17:39.312767378 [17803/17811]: Dispatching UST registration pid:17436 ppid:16398 uid:1000 gid:1000 sock:33 name:hello-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
74
DEBUG1 - 16:17:39.312751760 [17803/17812]: UST registration received with pid:17436 ppid:16398 uid:1000 gid:1000 sock:37 name:hello-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
75
DEBUG3 - 16:17:39.312776897 [17803/17811]: UST app creating application for socket 33 (in ust_app_create() at ust-app.c:3365)
76
DEBUG1 - 16:17:39.312779555 [17803/17812]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
77
DEBUG1 - 16:17:39.312794266 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
78
DEBUG3 - 16:17:39.312795625 [17803/17811]: Created hashtable size 4 at 0x1282250 of type 2 (in lttng_ht_new() at hashtable.c:145)
79
DEBUG3 - 16:17:39.312802445 [17803/17811]: Created hashtable size 4 at 0x1285510 of type 1 (in lttng_ht_new() at hashtable.c:145)
80
DEBUG3 - 16:17:39.312805400 [17803/17811]: Created hashtable size 4 at 0x1285a50 of type 1 (in lttng_ht_new() at hashtable.c:145)
81
DEBUG1 - 16:17:39.312818190 [17803/17811]: Dispatching UST registration pid:17436 ppid:16398 uid:1000 gid:1000 sock:37 name:hello-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
82
DEBUG3 - 16:17:39.312821308 [17803/17811]: UST app notify socket 37 is set (in thread_dispatch_ust_registration() at main.c:1853)
83
DEBUG1 - 16:17:39.312835314 [17803/17811]: App registered with pid:17436 ppid:16398 uid:1000 gid:1000 sock:33 name:hello-ust notify_sock:37 (version 7.2) (in ust_app_add() at ust-app.c:3454)
84
DEBUG3 - 16:17:39.312894396 [17803/17814]: [ust-thread] Manage notify return from poll on 2 fds (in ust_thread_manage_notify() at ust-thread.c:76)
85
DEBUG3 - 16:17:39.312909821 [17803/17814]: UST thread notify added sock 37 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
86
DEBUG1 - 16:17:39.312911308 [17803/17811]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
87
DEBUG3 - 16:17:39.312912983 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
88
DEBUG1 - 16:17:39.312915520 [17803/17811]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
89
DEBUG1 - 16:17:39.312918419 [17803/17811]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
90
DEBUG1 - 16:17:39.312916038 [17803/17813]: Apps thread return from poll on 2 fds (in thread_manage_apps() at main.c:1480)
91
DEBUG1 - 16:17:39.312921854 [17803/17811]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
92
DEBUG1 - 16:17:39.312935934 [17803/17813]: Apps with sock 33 added to poll set (in thread_manage_apps() at main.c:1537)
93
DEBUG1 - 16:17:39.312939509 [17803/17813]: Apps thread polling (in thread_manage_apps() at main.c:1473)
94
DEBUG1 - 16:17:39.355293923 [17803/17812]: UST registration received with pid:12709 ppid:1 uid:1000 gid:1000 sock:38 name:pbs-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
95
DEBUG1 - 16:17:39.355304296 [17803/17812]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
96
DEBUG1 - 16:17:39.355307126 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
97
DEBUG1 - 16:17:39.355307112 [17803/17811]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
98
DEBUG1 - 16:17:39.355312159 [17803/17811]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
99
DEBUG1 - 16:17:39.355314652 [17803/17811]: Dispatching UST registration pid:12709 ppid:1 uid:1000 gid:1000 sock:38 name:pbs-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
100
DEBUG1 - 16:17:39.355317130 [17803/17812]: UST registration received with pid:12709 ppid:1 uid:1000 gid:1000 sock:39 name:pbs-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
101
DEBUG3 - 16:17:39.355317754 [17803/17811]: UST app creating application for socket 38 (in ust_app_create() at ust-app.c:3365)
102
DEBUG1 - 16:17:39.355324168 [17803/17812]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
103
DEBUG3 - 16:17:39.355328877 [17803/17811]: Created hashtable size 4 at 0x128b7a0 of type 2 (in lttng_ht_new() at hashtable.c:145)
104
DEBUG1 - 16:17:39.355329148 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
105
DEBUG3 - 16:17:39.355344071 [17803/17811]: Created hashtable size 4 at 0x128bc50 of type 1 (in lttng_ht_new() at hashtable.c:145)
106
DEBUG3 - 16:17:39.355347547 [17803/17811]: Created hashtable size 4 at 0x128c100 of type 1 (in lttng_ht_new() at hashtable.c:145)
107
DEBUG1 - 16:17:39.355354838 [17803/17812]: UST registration received with pid:7905 ppid:15383 uid:1000 gid:1000 sock:40 name:mysqld-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
108
DEBUG1 - 16:17:39.355356973 [17803/17811]: Dispatching UST registration pid:12709 ppid:1 uid:1000 gid:1000 sock:39 name:pbs-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
109
DEBUG1 - 16:17:39.355358271 [17803/17812]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
110
DEBUG3 - 16:17:39.355361298 [17803/17811]: UST app notify socket 39 is set (in thread_dispatch_ust_registration() at main.c:1853)
111
DEBUG1 - 16:17:39.355363101 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
112
DEBUG1 - 16:17:39.355364867 [17803/17811]: App registered with pid:12709 ppid:1 uid:1000 gid:1000 sock:38 name:pbs-ust notify_sock:39 (version 7.2) (in ust_app_add() at ust-app.c:3454)
113
DEBUG1 - 16:17:39.355372875 [17803/17812]: UST registration received with pid:7905 ppid:15383 uid:1000 gid:1000 sock:41 name:mysqld-ust (version 7.2) (in thread_registration_apps() at main.c:2155)
114
DEBUG1 - 16:17:39.355375970 [17803/17812]: Futex n to 1 wake done (in futex_nto1_wake() at futex.c:122)
115
DEBUG1 - 16:17:39.355378124 [17803/17812]: Accepting application registration (in thread_registration_apps() at main.c:2039)
116
DEBUG3 - 16:17:39.355413503 [17803/17814]: [ust-thread] Manage notify return from poll on 3 fds (in ust_thread_manage_notify() at ust-thread.c:76)
117
DEBUG3 - 16:17:39.355420933 [17803/17814]: UST thread notify added sock 39 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
118
DEBUG3 - 16:17:39.355423592 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
119
DEBUG1 - 16:17:39.355454426 [17803/17811]: Dispatching UST registration pid:7905 ppid:15383 uid:1000 gid:1000 sock:40 name:mysqld-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
120
DEBUG1 - 16:17:39.355456735 [17803/17813]: Apps thread return from poll on 3 fds (in thread_manage_apps() at main.c:1480)
121
DEBUG3 - 16:17:39.355457795 [17803/17811]: UST app creating application for socket 40 (in ust_app_create() at ust-app.c:3365)
122
DEBUG1 - 16:17:39.355466389 [17803/17813]: Apps with sock 38 added to poll set (in thread_manage_apps() at main.c:1537)
123
DEBUG3 - 16:17:39.355468160 [17803/17811]: Created hashtable size 4 at 0x128c5b0 of type 2 (in lttng_ht_new() at hashtable.c:145)
124
DEBUG1 - 16:17:39.355469360 [17803/17813]: Apps thread polling (in thread_manage_apps() at main.c:1473)
125
DEBUG3 - 16:17:39.355472819 [17803/17811]: Created hashtable size 4 at 0x128ca60 of type 1 (in lttng_ht_new() at hashtable.c:145)
126
DEBUG3 - 16:17:39.355477552 [17803/17811]: Created hashtable size 4 at 0x128cf10 of type 1 (in lttng_ht_new() at hashtable.c:145)
127
DEBUG1 - 16:17:39.355486101 [17803/17811]: Dispatching UST registration pid:7905 ppid:15383 uid:1000 gid:1000 sock:41 name:mysqld-ust (version 7.2) (in thread_dispatch_ust_registration() at main.c:1796)
128
DEBUG3 - 16:17:39.355488753 [17803/17811]: UST app notify socket 41 is set (in thread_dispatch_ust_registration() at main.c:1853)
129
DEBUG1 - 16:17:39.355491558 [17803/17811]: App registered with pid:7905 ppid:15383 uid:1000 gid:1000 sock:40 name:mysqld-ust notify_sock:41 (version 7.2) (in ust_app_add() at ust-app.c:3454)
130
DEBUG3 - 16:17:39.355517672 [17803/17814]: [ust-thread] Manage notify return from poll on 4 fds (in ust_thread_manage_notify() at ust-thread.c:76)
131
DEBUG3 - 16:17:39.355523630 [17803/17814]: UST thread notify added sock 41 to pollset (in ust_thread_manage_notify() at ust-thread.c:137)
132
DEBUG3 - 16:17:39.355525960 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
133
DEBUG1 - 16:17:39.355532153 [17803/17811]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
134
DEBUG1 - 16:17:39.355533842 [17803/17813]: Apps thread return from poll on 4 fds (in thread_manage_apps() at main.c:1480)
135
DEBUG1 - 16:17:39.355535136 [17803/17811]: Futex n to 1 wait done (in futex_nto1_wait() at futex.c:105)
136
DEBUG1 - 16:17:39.355540067 [17803/17811]: Futex n to 1 prepare done (in futex_nto1_prepare() at futex.c:77)
137
DEBUG1 - 16:17:39.355540186 [17803/17813]: Apps with sock 40 added to poll set (in thread_manage_apps() at main.c:1537)
138
DEBUG1 - 16:17:39.355543460 [17803/17811]: Woken up but nothing in the UST command queue (in thread_dispatch_ust_registration() at main.c:1784)
139
DEBUG1 - 16:17:39.355545069 [17803/17813]: Apps thread polling (in thread_manage_apps() at main.c:1473)
140
DEBUG2 - 16:18:06.141450397 [17803/17815]: IP address resolved to 127.0.0.1 (in set_ip_address() at uri.c:165)
141
DEBUG3 - 16:18:06.141466604 [17803/17815]: URI dtype: 1, proto: 1, host: localhost, subdir: , ctrl: 0, data: 0 (in uri_parse() at uri.c:538)
142
DEBUG3 - 16:18:06.141482507 [17803/17815]: [agent-thread] Trying to bind on port 5345 (in init_tcp_socket() at agent-thread.c:118)
143
DEBUG1 - 16:18:06.141493250 [17803/17815]: [agent-thread] Listening on TCP port 5345 and socket 36 (in init_tcp_socket() at agent-thread.c:155)
144
DEBUG1 - 16:18:06.141593223 [17803/17815]: Pid 5345 written in file /var/lib/log/lttng_home/.lttng/agent.port (in utils_create_pid_file() at utils.c:507)
145
DEBUG3 - 16:18:06.141602677 [17803/17815]: [agent-thread] Manage agent polling (in agent_thread_manage_registration() at agent-thread.c:348)
146
DEBUG1 - 16:18:06.142188229 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
147
DEBUG1 - 16:18:38.213241643 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
148
DEBUG1 - 16:18:38.213285433 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
149
DEBUG1 - 16:18:38.213291763 [17803/17810]: Nothing recv() from client... continuing (in thread_manage_clients() at main.c:4438)
150
DEBUG1 - 16:18:38.213300265 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
151
DEBUG1 - 16:18:38.213304530 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
152
DEBUG1 - 16:18:38.213330034 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
153
DEBUG1 - 16:18:38.213339809 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
154
DEBUG1 - 16:18:38.213357242 [17803/17810]: Processing client command 8 (in process_client_msg() at main.c:2877)
155
DEBUG1 - 16:18:38.213368703 [17803/17810]: Waiting for 1 URIs from client ... (in process_client_msg() at main.c:3660)
156
DEBUG2 - 16:18:38.213377521 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
157
DEBUG3 - 16:18:38.213403946 [17803/17810]: Created hashtable size 4 at 0x1291940 of type 1 (in lttng_ht_new() at hashtable.c:145)
158
DEBUG1 - 16:18:38.213408423 [17803/17810]: Allocating ltt_sessions_ht_by_id (in ltt_sessions_ht_alloc() at session.c:153)
159
DEBUG3 - 16:18:38.213414099 [17803/17810]: Created hashtable size 4 at 0x1291df0 of type 2 (in lttng_ht_new() at hashtable.c:145)
160
DEBUG1 - 16:18:38.213417805 [17803/17810]: Tracing session auto-20200114-161838 created with ID 0 by UID 1000 GID 1000 (in session_create() at session.c:420)
161
DEBUG2 - 16:18:38.213420739 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
162
DEBUG3 - 16:18:38.213438584 [17803/17810]: Created hashtable size 4 at 0x1297310 of type 1 (in lttng_ht_new() at hashtable.c:145)
163
DEBUG2 - 16:18:38.213442365 [17803/17810]: Setting trace directory path from URI to /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838 (in add_uri_to_consumer() at cmd.c:787)
164
DEBUG1 - 16:18:38.213452104 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
165
DEBUG1 - 16:18:38.213463357 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
166
DEBUG1 - 16:18:38.213465911 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
167
DEBUG1 - 16:18:58.666145912 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
168
DEBUG1 - 16:18:58.666172602 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
169
DEBUG1 - 16:18:58.666181541 [17803/17810]: Processing client command 6 (in process_client_msg() at main.c:2877)
170
DEBUG1 - 16:18:58.666185315 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
171
DEBUG2 - 16:18:58.666188526 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
172
DEBUG1 - 16:18:58.666192317 [17803/17810]: Creating UST session (in create_ust_session() at main.c:2748)
173
DEBUG3 - 16:18:58.666207010 [17803/17810]: Created hashtable size 4 at 0x12832a0 of type 0 (in lttng_ht_new() at hashtable.c:145)
174
DEBUG3 - 16:18:58.666211527 [17803/17810]: Created hashtable size 4 at 0x12837e0 of type 2 (in lttng_ht_new() at hashtable.c:145)
175
DEBUG3 - 16:18:58.666228761 [17803/17810]: Created hashtable size 4 at 0x1283d20 of type 1 (in lttng_ht_new() at hashtable.c:145)
176
DEBUG2 - 16:18:58.666231470 [17803/17810]: UST trace session create successful (in trace_ust_create_session() at trace-ust.c:320)
177
DEBUG3 - 16:18:58.666236562 [17803/17810]: Copying tracing session consumer output in UST session (in copy_session_consumer() at main.c:2695)
178
DEBUG3 - 16:18:58.666257174 [17803/17810]: Created hashtable size 4 at 0x1284260 of type 1 (in lttng_ht_new() at hashtable.c:145)
179
DEBUG3 - 16:18:58.666256477 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
180
DEBUG3 - 16:18:58.666280008 [17803/17810]: Copy session consumer subdir /ust (in copy_session_consumer() at main.c:2713)
181
DEBUG1 - 16:18:58.666285145 [17803/17810]: Spawning consumerd (in spawn_consumerd() at main.c:2379)
182
DEBUG2 - 16:18:58.666488805 [17803/17810]: Consumer pid 19216 (in start_consumerd() at main.c:2556)
183
DEBUG2 - 16:18:58.666503174 [17803/17810]: Spawning consumer control thread (in start_consumerd() at main.c:2559)
184
DEBUG1 - 16:18:58.666546701 [17803/19217]: [thread] Manage consumer started (in thread_manage_consumer() at main.c:1085)
185
DEBUG1 - 16:18:58.666621953 [19216/19216]: Using 64-bit UST consumer at: /usr/lib64/lttng/libexec/lttng-consumerd (in spawn_consumerd() at main.c:2457)
186
DEBUG1 - 16:18:58.667645854 [19216/19216]: Health check time delta in seconds set to 20 (in health_init() at health.c:73)
187
DEBUG1 - 16:18:58.671635758 [19216/19216]: TCP inet operation timeout set to 180 sec (in lttcomm_inet_init() at inet.c:546)
188
DEBUG1 - 16:18:58.671766220 [19219/19219]: Resetting run_as worker signal handlers to default (in reset_sighandler() at runas.c:536)
189
DEBUG1 - 16:18:58.671851045 [19219/19219]: run_as signal handler set for SIGTERM and SIGINT (in set_worker_sighandlers() at runas.c:597)
190
DEBUG1 - 16:18:58.671918949 [19216/19216]: Connecting to error socket /var/lib/log/lttng_home/.lttng/ustconsumerd64/error (in main() at lttng-consumerd.c:464)
191
DEBUG2 - 16:18:58.671957182 [17803/19217]: Receiving code from consumer err_sock (in thread_manage_consumer() at main.c:1183)
192
DEBUG1 - 16:18:58.671999505 [19216/19220]: [thread] Manage health check started (in thread_manage_health() at health-consumerd.c:167)
193
DEBUG1 - 16:18:58.672083073 [19216/19220]: epoll set max size is 74124963 (in compat_epoll_set_max_size() at compat-epoll.c:337)
194
DEBUG1 - 16:18:58.672098606 [19216/19220]: Health check ready (in thread_manage_health() at health-consumerd.c:240)
195
DEBUG3 - 16:18:58.676366836 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
196
DEBUG1 - 16:18:58.772105324 [19216/19222]: Thread channel poll started (in consumer_thread_channel_poll() at consumer.c:2855)
197
DEBUG1 - 16:18:58.772124467 [19216/19223]: Thread metadata poll started (in consumer_thread_metadata_poll() at consumer.c:2259)
198
DEBUG1 - 16:18:58.772158457 [19216/19224]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
199
DEBUG1 - 16:18:58.772170559 [19216/19223]: Metadata main loop started (in consumer_thread_metadata_poll() at consumer.c:2275)
200
DEBUG1 - 16:18:58.772173826 [19216/19224]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2544)
201
DEBUG1 - 16:18:58.772132719 [19216/19222]: Channel main loop started (in consumer_thread_channel_poll() at consumer.c:2870)
202
DEBUG1 - 16:18:58.772188088 [19216/19225]: Creating command socket /var/lib/log/lttng_home/.lttng/ustconsumerd64/command (in consumer_thread_sessiond_poll() at consumer.c:3123)
203
DEBUG1 - 16:18:58.772193947 [19216/19222]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2875)
204
DEBUG1 - 16:18:58.772176604 [19216/19223]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
205
DEBUG1 - 16:18:58.772235101 [19216/19225]: Sending ready command to lttng-sessiond (in consumer_thread_sessiond_poll() at consumer.c:3136)
206
DEBUG1 - 16:18:58.772263066 [19216/19225]: Connection on client_socket (in consumer_thread_sessiond_poll() at consumer.c:3158)
207
DEBUG1 - 16:18:58.772266171 [17803/19217]: Consumer command socket ready (fd: 45 (in thread_manage_consumer() at main.c:1223)
208
DEBUG1 - 16:18:58.772271077 [19216/19225]: Metadata connection on client_socket (in set_metadata_socket() at consumer.c:3084)
209
DEBUG1 - 16:18:58.772272352 [17803/19217]: Consumer metadata socket ready (fd: 46) (in thread_manage_consumer() at main.c:1225)
210
DEBUG3 - 16:18:58.772287037 [17803/19217]: Sending set_channel_monitor_pipe command to consumer (in consumer_send_channel_monitor_pipe() at consumer.c:1078)
211
DEBUG1 - 16:18:58.772304786 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
212
DEBUG3 - 16:18:58.772329880 [17803/19217]: Sending channel monitoring pipe 14 to consumer on socket 45 (in consumer_send_channel_monitor_pipe() at consumer.c:1085)
213
DEBUG1 - 16:18:58.772353148 [19216/19225]: Received channel monitor pipe (27) (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1899)
214
DEBUG1 - 16:18:58.772364341 [19216/19225]: Channel monitor pipe set as non-blocking (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1920)
215
DEBUG1 - 16:18:58.772369361 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
216
DEBUG2 - 16:18:58.772371754 [17803/19217]: Channel monitoring pipe successfully sent (in consumer_send_channel_monitor_pipe() at consumer.c:1091)
217
DEBUG3 - 16:18:58.772412085 [17803/17810]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
218
DEBUG1 - 16:18:58.772421222 [17803/17810]: Setting relayd for session auto-20200114-161838 (in cmd_setup_relayd() at cmd.c:1043)
219
DEBUG1 - 16:18:58.772427244 [17803/17810]: Enable event command for event 'hello_world:my_first_tracepoint' (in _cmd_enable_event() at cmd.c:1864)
220
DEBUG2 - 16:18:58.772431344 [17803/17810]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
221
DEBUG1 - 16:18:58.772439454 [17803/17810]: Enabling channel  for session auto-20200114-161838 (in cmd_enable_channel() at cmd.c:1346)
222
DEBUG2 - 16:18:58.772442251 [17803/17810]: Trace UST channel channel0 not found by name (in trace_ust_find_channel_by_name() at trace-ust.c:196)
223
DEBUG3 - 16:18:58.772446726 [17803/17810]: Created hashtable size 4 at 0x1284d80 of type 0 (in lttng_ht_new() at hashtable.c:145)
224
DEBUG3 - 16:18:58.772451277 [17803/17810]: Created hashtable size 4 at 0x129ea00 of type 1 (in lttng_ht_new() at hashtable.c:145)
225
DEBUG2 - 16:18:58.772453713 [17803/17810]: Trace UST channel channel0 created (in trace_ust_create_channel() at trace-ust.c:395)
226
DEBUG2 - 16:18:58.772457121 [17803/17810]: Channel channel0 is being created for UST with buffer 1 and id 0 (in channel_ust_create() at channel.c:455)
227
DEBUG2 - 16:18:58.772461671 [17803/17810]: UST app adding channel channel0 to UST domain for session id 0 (in ust_app_create_channel_glb() at ust-app.c:4144)
228
DEBUG2 - 16:18:58.772469667 [17803/17810]: UST app pid: 12709 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2172)
229
DEBUG3 - 16:18:58.772486972 [17803/17810]: Created hashtable size 4 at 0x12a1fe0 of type 0 (in lttng_ht_new() at hashtable.c:145)
230
DEBUG2 - 16:18:58.772504938 [17803/17810]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1870)
231
DEBUG3 - 16:18:58.772513991 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
232
DEBUG3 - 16:18:58.772523669 [17803/17810]: Created hashtable size 4 at 0x12a44f0 of type 2 (in lttng_ht_new() at hashtable.c:145)
233
DEBUG3 - 16:18:58.772526171 [17803/17810]: Buffer registry per UID created id: 0, ABI: 64, uid: 1000, domain: 2 (in buffer_reg_uid_create() at buffer-registry.c:152)
234
DEBUG3 - 16:18:58.772537218 [17803/17810]: Created hashtable size 4 at 0x12a7ac0 of type 0 (in lttng_ht_new() at hashtable.c:145)
235
DEBUG3 - 16:18:58.772542326 [17803/17810]: Created hashtable size 4 at 0x12a8000 of type 2 (in lttng_ht_new() at hashtable.c:145)
236
DEBUG3 - 16:18:58.772582579 [17803/17810]: Append to metadata: "/* CTF 1.8 */
237

    
238
" (in lttng_metadata_printf() at ust-metadata.c:178)
239
DEBUG3 - 16:18:58.772590748 [17803/17810]: Append to metadata: "typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
240
typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
241
typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
242
typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
243
typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
244
typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
245
typealias integer { size = 27; align = 1; signed = false; } := uint27_t;
246

    
247
trace {
248
	major = 1;
249
	minor = 8;
250
	uuid = "80c2cf72-d481-4dc2-9a14-e62b29f73213";
251
	byte_order = le;
252
	packet.header := struct {
253
		uint32_t magic;
254
		uint8_t  uuid[16];
255
		uint32_t stream_id;
256
		uint64_t stream_instance_id;
257
	};
258
};
259

    
260
" (in lttng_metadata_printf() at ust-metadata.c:178)
261
DEBUG3 - 16:18:58.772597229 [17803/17810]: Append to metadata: "env {
262
	hostname = "localhost.localdomain";
263
	domain = "ust";
264
	tracer_name = "lttng-ust";
265
	tracer_major = 2;
266
	tracer_minor = 10;
267
" (in lttng_metadata_printf() at ust-metadata.c:178)
268
DEBUG3 - 16:18:58.772600362 [17803/17810]: Append to metadata: "};
269

    
270
" (in lttng_metadata_printf() at ust-metadata.c:178)
271
DEBUG3 - 16:18:58.772603218 [17803/17810]: Append to metadata: "clock {
272
	name = "monotonic";
273
" (in lttng_metadata_printf() at ust-metadata.c:178)
274
DEBUG3 - 16:18:58.772624614 [17803/17810]: Append to metadata: "	uuid = "86ee69d8-dedc-429a-a5ee-5ffa3686ad13";
275
" (in lttng_metadata_printf() at ust-metadata.c:178)
276
DEBUG3 - 16:18:58.772630391 [17803/17810]: Append to metadata: "	description = "Monotonic Clock";
277
	freq = 1000000000; /* Frequency, in Hz */
278
	/* clock value offset from Epoch is: offset * (1/freq) */
279
	offset = 1576467154520961239;
280
};
281

    
282
" (in lttng_metadata_printf() at ust-metadata.c:178)
283
DEBUG3 - 16:18:58.772635336 [17803/17810]: Append to metadata: "typealias integer {
284
	size = 27; align = 1; signed = false;
285
	map = clock.monotonic.value;
286
} := uint27_clock_monotonic_t;
287

    
288
typealias integer {
289
	size = 32; align = 8; signed = false;
290
	map = clock.monotonic.value;
291
} := uint32_clock_monotonic_t;
292

    
293
typealias integer {
294
	size = 64; align = 8; signed = false;
295
	map = clock.monotonic.value;
296
} := uint64_clock_monotonic_t;
297

    
298
" (in lttng_metadata_printf() at ust-metadata.c:178)
299
DEBUG3 - 16:18:58.772639347 [17803/17810]: Append to metadata: "struct packet_context {
300
	uint64_clock_monotonic_t timestamp_begin;
301
	uint64_clock_monotonic_t timestamp_end;
302
	uint64_t content_size;
303
	uint64_t packet_size;
304
	uint64_t packet_seq_num;
305
	unsigned long events_discarded;
306
	uint32_t cpu_id;
307
};
308

    
309
" (in lttng_metadata_printf() at ust-metadata.c:178)
310
DEBUG3 - 16:18:58.772645604 [17803/17810]: Append to metadata: "struct event_header_compact {
311
	enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
312
	variant <id> {
313
		struct {
314
			uint27_clock_monotonic_t timestamp;
315
		} compact;
316
		struct {
317
			uint32_t id;
318
			uint64_clock_monotonic_t timestamp;
319
		} extended;
320
	} v;
321
} align(8);
322

    
323
struct event_header_large {
324
	enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
325
	variant <id> {
326
		struct {
327
			uint32_clock_monotonic_t timestamp;
328
		} compact;
329
		struct {
330
			uint32_t id;
331
			uint64_clock_monotonic_t timestamp;
332
		} extended;
333
	} v;
334
} align(8);
335

    
336
" (in lttng_metadata_printf() at ust-metadata.c:178)
337
DEBUG3 - 16:18:58.772649410 [17803/17810]: Buffer registry per UID adding to global registry with id: 0 (in buffer_reg_uid_add() at buffer-registry.c:174)
338
DEBUG3 - 16:18:58.772652294 [17803/17810]: UST app buffer registry per UID created successfully (in setup_buffer_reg_uid() at ust-app.c:2135)
339
DEBUG2 - 16:18:58.772763324 [17803/17810]: UST app session created successfully with handle 4 (in create_ust_app_session() at ust-app.c:2247)
340
DEBUG3 - 16:18:58.772769027 [17803/17810]: Created hashtable size 4 at 0x12a8770 of type 1 (in lttng_ht_new() at hashtable.c:145)
341
DEBUG3 - 16:18:58.772771872 [17803/17810]: Created hashtable size 4 at 0x12a8cb0 of type 0 (in lttng_ht_new() at hashtable.c:145)
342
DEBUG3 - 16:18:58.772774206 [17803/17810]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1049)
343
DEBUG2 - 16:18:58.772776853 [17803/17810]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1792)
344
DEBUG3 - 16:18:58.772779564 [17803/17810]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1846)
345
DEBUG1 - 16:18:58.772783467 [17803/17810]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2864)
346
DEBUG3 - 16:18:58.772786159 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
347
DEBUG2 - 16:18:58.772789314 [17803/17810]: UST app creating buffer registry channel for channel0 (in create_buffer_reg_channel() at ust-app.c:2708)
348
DEBUG3 - 16:18:58.772791910 [17803/17810]: Buffer registry channel create with key: 0 (in buffer_reg_channel_create() at buffer-registry.c:380)
349
DEBUG3 - 16:18:58.772796183 [17803/17810]: Created hashtable size 4 at 0x12aa330 of type 0 (in lttng_ht_new() at hashtable.c:145)
350
DEBUG3 - 16:18:58.772802135 [17803/17810]: Session 0 found by id. (in session_find_by_id() at session.c:312)
351
DEBUG2 - 16:18:58.772808039 [17803/17810]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:121)
352
DEBUG3 - 16:18:58.772817078 [17803/17810]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838/ust/uid/1000/64-bit with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
353
DEBUG1 - 16:18:58.772825971 [17803/17810]: Using run_as worker (in run_as() at runas.c:450)
354
DEBUG3 - 16:18:58.772997254 [17803/17810]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
355
DEBUG1 - 16:18:58.773009765 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
356
DEBUG1 - 16:18:58.773026317 [19216/19225]: Allocated channel (key 1) (in consumer_allocate_channel() at consumer.c:1031)
357
DEBUG1 - 16:18:58.779662531 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
358
DEBUG1 - 16:18:58.779739270 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
359
DEBUG1 - 16:18:58.779800999 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
360
DEBUG1 - 16:18:58.779836276 [19216/19225]: utils_unlink_stream_file /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838/ust/uid/1000/64-bit/index/channel0_0.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
361
DEBUG1 - 16:18:58.779845576 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
362
DEBUG1 - 16:18:58.779887415 [19216/19225]: UST consumer add stream channel0_0 (key: 38) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
363
DEBUG1 - 16:18:58.779896404 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
364
DEBUG1 - 16:18:58.779928122 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
365
DEBUG1 - 16:18:58.779954357 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
366
DEBUG1 - 16:18:58.779983374 [19216/19225]: utils_unlink_stream_file /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838/ust/uid/1000/64-bit/index/channel0_1.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
367
DEBUG1 - 16:18:58.779991620 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
368
DEBUG1 - 16:18:58.780022268 [19216/19225]: UST consumer add stream channel0_1 (key: 40) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
369
DEBUG1 - 16:18:58.780030537 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
370
DEBUG1 - 16:18:58.780062266 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
371
DEBUG1 - 16:18:58.780088701 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
372
DEBUG1 - 16:18:58.780111591 [19216/19225]: utils_unlink_stream_file /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838/ust/uid/1000/64-bit/index/channel0_2.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
373
DEBUG1 - 16:18:58.780119568 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
374
DEBUG1 - 16:18:58.780152724 [19216/19225]: UST consumer add stream channel0_2 (key: 42) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
375
DEBUG1 - 16:18:58.780160414 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
376
DEBUG1 - 16:18:58.780192420 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
377
DEBUG1 - 16:18:58.780218499 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
378
DEBUG1 - 16:18:58.780241514 [19216/19225]: utils_unlink_stream_file /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838/ust/uid/1000/64-bit/index/channel0_3.idx returns -1 (in utils_unlink_stream_file() at utils.c:830)
379
DEBUG1 - 16:18:58.780249278 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
380
DEBUG1 - 16:18:58.780281499 [19216/19225]: UST consumer add stream channel0_3 (key: 44) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
381
DEBUG1 - 16:18:58.780304235 [19216/19225]: UST consumer channel added (key: 1) (in add_channel() at ust-consumer.c:115)
382
DEBUG1 - 16:18:58.780308498 [19216/19222]: Channel poll return from wait with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2879)
383
DEBUG2 - 16:18:58.780315283 [17803/17810]: UST ask channel 1 successfully done with 4 stream(s) (in ask_channel_creation() at ust-consumer.c:218)
384
DEBUG1 - 16:18:58.780316766 [19216/19222]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2881)
385
DEBUG1 - 16:18:58.780311245 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
386
DEBUG1 - 16:18:58.780324454 [19216/19222]: Adding channel 35 to poll set (in consumer_thread_channel_poll() at consumer.c:2924)
387
DEBUG1 - 16:18:58.780328043 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
388
DEBUG1 - 16:18:58.780330517 [19216/19222]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2875)
389
DEBUG1 - 16:18:58.780336016 [19216/19225]: UST consumer sending channel channel0 to sessiond (in send_sessiond_channel() at ust-consumer.c:562)
390
DEBUG1 - 16:18:58.780356732 [19216/19225]: UST consumer sending stream 38 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
391
DEBUG1 - 16:18:58.780373301 [19216/19225]: UST consumer sending stream 40 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
392
DEBUG2 - 16:18:58.780375782 [17803/17810]: UST app stream 1 received successfully (in ust_consumer_get_channel() at ust-consumer.c:339)
393
DEBUG1 - 16:18:58.780380111 [19216/19225]: UST consumer sending stream 42 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
394
DEBUG1 - 16:18:58.780386938 [19216/19225]: UST consumer sending stream 44 to sessiond (in send_sessiond_stream() at ust-consumer.c:533)
395
DEBUG2 - 16:18:58.780388004 [17803/17810]: UST app stream 2 received successfully (in ust_consumer_get_channel() at ust-consumer.c:339)
396
DEBUG1 - 16:18:58.780394068 [19216/19225]: UST consumer NULL stream sent to sessiond (in send_sessiond_channel() at ust-consumer.c:626)
397
DEBUG2 - 16:18:58.780397112 [17803/17810]: UST app stream 3 received successfully (in ust_consumer_get_channel() at ust-consumer.c:339)
398
DEBUG2 - 16:18:58.780405310 [17803/17810]: UST app stream 4 received successfully (in ust_consumer_get_channel() at ust-consumer.c:339)
399
DEBUG1 - 16:18:58.780411204 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
400
DEBUG3 - 16:18:58.780414398 [17803/17810]: UST app consumer has no more stream available (in ust_consumer_get_channel() at ust-consumer.c:323)
401
DEBUG1 - 16:18:58.780411016 [19216/19224]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
402
DEBUG2 - 16:18:58.780418631 [17803/17810]: UST app setup buffer registry channel for channel0 (in setup_buffer_reg_channel() at ust-app.c:2758)
403
DEBUG2 - 16:18:58.780421379 [17803/17810]: UST app setup buffer registry stream (in setup_buffer_reg_streams() at ust-app.c:2663)
404
DEBUG1 - 16:18:58.780421031 [19216/19224]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2581)
405
DEBUG3 - 16:18:58.780423800 [17803/17810]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
406
DEBUG3 - 16:18:58.780427179 [17803/17810]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
407
DEBUG1 - 16:18:58.780426948 [19216/19224]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
408
DEBUG3 - 16:18:58.780429595 [17803/17810]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
409
DEBUG3 - 16:18:58.780432113 [17803/17810]: Buffer registry creating stream (in buffer_reg_stream_create() at buffer-registry.c:410)
410
DEBUG1 - 16:18:58.780432408 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
411
DEBUG3 - 16:18:58.780434557 [17803/17810]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
412
DEBUG1 - 16:18:58.780437090 [19216/19224]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
413
DEBUG3 - 16:18:58.780437259 [17803/17810]: Session 0 found by id. (in session_find_by_id() at session.c:312)
414
DEBUG1 - 16:18:58.780439665 [19216/19224]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2581)
415
DEBUG1 - 16:18:58.780442729 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
416
DEBUG1 - 16:18:58.780446003 [19216/19224]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
417
DEBUG1 - 16:18:58.780447466 [17803/17810]: Beginning of waiter wait period (in lttng_waiter_wait() at waiter.c:58)
418
DEBUG1 - 16:18:58.780448187 [19216/19224]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2581)
419
DEBUG1 - 16:18:58.780451156 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
420
DEBUG1 - 16:18:58.780454423 [19216/19224]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
421
DEBUG1 - 16:18:58.780457958 [19216/19224]: consumer_data_pipe wake up (in consumer_thread_data_poll() at consumer.c:2581)
422
DEBUG1 - 16:18:58.780454811 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
423
DEBUG1 - 16:18:58.780461373 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
424
DEBUG1 - 16:18:58.780463897 [17803/17809]: [notification-thread] Handling fd (24) activity (1) (in thread_notification() at notification-thread.c:530)
425
DEBUG1 - 16:18:58.780471106 [17803/17809]: [notification-thread] Received add channel command (in handle_notification_thread_command() at notification-thread-events.c:1300)
426
DEBUG1 - 16:18:58.780475614 [17803/17809]: [notification-thread] Adding channel channel0 from session auto-20200114-161838, channel key = 1 in user space domain (in handle_notification_thread_command_add_channel() at notification-thread-events.c:812)
427
DEBUG1 - 16:18:58.780483030 [17803/17809]: [notification-thread] Found 0 triggers that apply to newly added channel (in handle_notification_thread_command_add_channel() at notification-thread-events.c:844)
428
DEBUG1 - 16:18:58.780494013 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
429
DEBUG1 - 16:18:58.780494024 [17803/17810]: End of waiter wait period (in lttng_waiter_wait() at waiter.c:101)
430
DEBUG1 - 16:18:58.780498681 [17803/17810]: UST app sending buffer registry channel to ust sock 38 (in send_channel_uid_to_ust() at ust-app.c:2794)
431
DEBUG2 - 16:18:58.780504229 [17803/17810]: UST app send channel to sock 38 pid 12709 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:445)
432
DEBUG2 - 16:18:58.780554206 [17803/17810]: UST consumer send stream to app 38 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
433
DEBUG2 - 16:18:58.780597456 [17803/17810]: UST consumer send stream to app 38 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
434
DEBUG2 - 16:18:58.780627269 [17803/17810]: UST consumer send stream to app 38 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
435
DEBUG2 - 16:18:58.780654235 [17803/17810]: UST consumer send stream to app 38 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
436
DEBUG2 - 16:18:58.780683243 [17803/17810]: UST app create channel channel0 for PID 12709 completed (in create_ust_app_channel() at ust-app.c:3157)
437
DEBUG2 - 16:18:58.780688793 [17803/17810]: UST app pid: 7905 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2172)
438
DEBUG3 - 16:18:58.780697790 [17803/17810]: Created hashtable size 4 at 0x12ab310 of type 0 (in lttng_ht_new() at hashtable.c:145)
439
DEBUG2 - 16:18:58.780705489 [17803/17810]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1870)
440
DEBUG3 - 16:18:58.780709143 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
441
DEBUG2 - 16:18:58.780804889 [17803/17810]: UST app session created successfully with handle 4 (in create_ust_app_session() at ust-app.c:2247)
442
DEBUG3 - 16:18:58.780809691 [17803/17810]: Created hashtable size 4 at 0x12aba80 of type 1 (in lttng_ht_new() at hashtable.c:145)
443
DEBUG3 - 16:18:58.780812588 [17803/17810]: Created hashtable size 4 at 0x12ad530 of type 0 (in lttng_ht_new() at hashtable.c:145)
444
DEBUG3 - 16:18:58.780814952 [17803/17810]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1049)
445
DEBUG2 - 16:18:58.780817300 [17803/17810]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1792)
446
DEBUG3 - 16:18:58.780819808 [17803/17810]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1846)
447
DEBUG1 - 16:18:58.780822214 [17803/17810]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2864)
448
DEBUG3 - 16:18:58.780824599 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
449
DEBUG1 - 16:18:58.780829330 [17803/17810]: UST app sending buffer registry channel to ust sock 40 (in send_channel_uid_to_ust() at ust-app.c:2794)
450
DEBUG2 - 16:18:58.780832620 [17803/17810]: UST app send channel to sock 40 pid 7905 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:445)
451
DEBUG2 - 16:18:58.780864588 [17803/17810]: UST consumer send stream to app 40 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
452
DEBUG2 - 16:18:58.780895921 [17803/17810]: UST consumer send stream to app 40 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
453
DEBUG2 - 16:18:58.780924783 [17803/17810]: UST consumer send stream to app 40 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
454
DEBUG2 - 16:18:58.780952813 [17803/17810]: UST consumer send stream to app 40 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
455
DEBUG2 - 16:18:58.780990137 [17803/17810]: UST app create channel channel0 for PID 7905 completed (in create_ust_app_channel() at ust-app.c:3157)
456
DEBUG2 - 16:18:58.780994698 [17803/17810]: UST app pid: 17436 session id 0 not found, creating it (in create_ust_app_session() at ust-app.c:2172)
457
DEBUG3 - 16:18:58.781003903 [17803/17810]: Created hashtable size 4 at 0x12adf70 of type 0 (in lttng_ht_new() at hashtable.c:145)
458
DEBUG2 - 16:18:58.781008755 [17803/17810]: Shadow copy of session handle -1 (in shadow_copy_session() at ust-app.c:1870)
459
DEBUG3 - 16:18:58.781011868 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
460
DEBUG2 - 16:18:58.781102210 [17803/17810]: UST app session created successfully with handle 1 (in create_ust_app_session() at ust-app.c:2247)
461
DEBUG3 - 16:18:58.781106518 [17803/17810]: Created hashtable size 4 at 0x12ae9f0 of type 1 (in lttng_ht_new() at hashtable.c:145)
462
DEBUG3 - 16:18:58.781109418 [17803/17810]: Created hashtable size 4 at 0x12aef30 of type 0 (in lttng_ht_new() at hashtable.c:145)
463
DEBUG3 - 16:18:58.781111736 [17803/17810]: UST app channel channel0 allocated (in alloc_ust_app_channel() at ust-app.c:1049)
464
DEBUG2 - 16:18:58.781114014 [17803/17810]: UST app shadow copy of channel channel0 started (in shadow_copy_channel() at ust-app.c:1792)
465
DEBUG3 - 16:18:58.781116344 [17803/17810]: UST app shadow copy of channel channel0 done (in shadow_copy_channel() at ust-app.c:1846)
466
DEBUG1 - 16:18:58.781118694 [17803/17810]: UST app creating channel channel0 with per UID buffers (in create_channel_per_uid() at ust-app.c:2864)
467
DEBUG3 - 16:18:58.781120963 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
468
DEBUG1 - 16:18:58.781123382 [17803/17810]: UST app sending buffer registry channel to ust sock 33 (in send_channel_uid_to_ust() at ust-app.c:2794)
469
DEBUG2 - 16:18:58.781126692 [17803/17810]: UST app send channel to sock 33 pid 17436 (name: channel0, key: 0) (in ust_consumer_send_channel_to_ust() at ust-consumer.c:445)
470
DEBUG2 - 16:18:58.782539612 [17803/17810]: UST consumer send stream to app 33 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
471
DEBUG2 - 16:18:58.782568942 [17803/17810]: UST consumer send stream to app 33 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
472
DEBUG2 - 16:18:58.782596656 [17803/17810]: UST consumer send stream to app 33 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
473
DEBUG2 - 16:18:58.782622435 [17803/17810]: UST consumer send stream to app 33 (in ust_consumer_send_stream_to_ust() at ust-consumer.c:408)
474
DEBUG2 - 16:18:58.782649871 [17803/17810]: UST app create channel channel0 for PID 17436 completed (in create_ust_app_channel() at ust-app.c:3157)
475
DEBUG2 - 16:18:58.782654174 [17803/17810]: Channel channel0 created successfully (in channel_ust_create() at channel.c:490)
476
DEBUG2 - 16:18:58.782657279 [17803/17810]: Trace UST channel channel0 found by name (in trace_ust_find_channel_by_name() at trace-ust.c:191)
477
DEBUG2 - 16:18:58.782661962 [17803/17810]: Trace UST event hello_world:my_first_tracepoint NOT found (in trace_ust_find_event() at trace-ust.c:234)
478
DEBUG2 - 16:18:58.782665007 [17803/17810]: Trace UST event hello_world:my_first_tracepoint, loglevel (0,-1) created (in trace_ust_create_event() at trace-ust.c:512)
479
DEBUG1 - 16:18:58.782668835 [17803/17810]: UST app creating event hello_world:my_first_tracepoint for all apps for session id 0 (in ust_app_create_event_glb() at ust-app.c:4328)
480
DEBUG3 - 16:18:58.782673384 [17803/17810]: UST app event hello_world:my_first_tracepoint allocated (in alloc_ust_app_event() at ust-app.c:1105)
481
DEBUG2 - 16:18:58.782698448 [17803/17810]: UST app event hello_world:my_first_tracepoint created successfully for pid:12709 (in create_ust_event() at ust-app.c:1692)
482
DEBUG2 - 16:18:58.782717559 [17803/17810]: UST app event hello_world:my_first_tracepoint enabled successfully for app (pid: 12709) (in enable_ust_event() at ust-app.c:1596)
483
DEBUG2 - 16:18:58.782720931 [17803/17810]: UST app create event hello_world:my_first_tracepoint for PID 12709 completed (in create_ust_app_event() at ust-app.c:3216)
484
DEBUG3 - 16:18:58.782724063 [17803/17810]: UST app event hello_world:my_first_tracepoint allocated (in alloc_ust_app_event() at ust-app.c:1105)
485
DEBUG2 - 16:18:58.782743691 [17803/17810]: UST app event hello_world:my_first_tracepoint created successfully for pid:7905 (in create_ust_event() at ust-app.c:1692)
486
DEBUG2 - 16:18:58.782761388 [17803/17810]: UST app event hello_world:my_first_tracepoint enabled successfully for app (pid: 7905) (in enable_ust_event() at ust-app.c:1596)
487
DEBUG2 - 16:18:58.782764192 [17803/17810]: UST app create event hello_world:my_first_tracepoint for PID 7905 completed (in create_ust_app_event() at ust-app.c:3216)
488
DEBUG3 - 16:18:58.782767016 [17803/17810]: UST app event hello_world:my_first_tracepoint allocated (in alloc_ust_app_event() at ust-app.c:1105)
489
DEBUG2 - 16:18:58.782788059 [17803/17810]: UST app event hello_world:my_first_tracepoint created successfully for pid:17436 (in create_ust_event() at ust-app.c:1692)
490
DEBUG2 - 16:18:58.782806145 [17803/17810]: UST app event hello_world:my_first_tracepoint enabled successfully for app (pid: 17436) (in enable_ust_event() at ust-app.c:1596)
491
DEBUG2 - 16:18:58.782808929 [17803/17810]: UST app create event hello_world:my_first_tracepoint for PID 17436 completed (in create_ust_app_event() at ust-app.c:3216)
492
DEBUG1 - 16:18:58.782811625 [17803/17810]: Event UST hello_world:my_first_tracepoint created in channel channel0 (in event_ust_enable_tracepoint() at event.c:236)
493
DEBUG1 - 16:18:58.782817424 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
494
DEBUG1 - 16:18:58.782829894 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
495
DEBUG1 - 16:18:58.782833006 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
496
DEBUG1 - 16:18:59.780332106 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
497
DEBUG1 - 16:18:59.780326837 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
498
DEBUG1 - 16:18:59.780345753 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
499
DEBUG1 - 16:18:59.780357463 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
500
DEBUG1 - 16:18:59.780364560 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
501
DEBUG1 - 16:19:00.780317204 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
502
DEBUG1 - 16:19:00.780323144 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
503
DEBUG1 - 16:19:00.780334889 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
504
DEBUG1 - 16:19:00.780343192 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
505
DEBUG1 - 16:19:00.780347914 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
506
DEBUG1 - 16:19:01.780316739 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
507
DEBUG1 - 16:19:01.780322304 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
508
DEBUG1 - 16:19:01.780333755 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
509
DEBUG1 - 16:19:01.780342904 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
510
DEBUG1 - 16:19:01.780348552 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
511
DEBUG1 - 16:19:02.780317611 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
512
DEBUG1 - 16:19:02.780323807 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
513
DEBUG1 - 16:19:02.780337322 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
514
DEBUG1 - 16:19:02.780345815 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
515
DEBUG1 - 16:19:02.780350416 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
516
DEBUG1 - 16:19:03.780318816 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
517
DEBUG1 - 16:19:03.780324076 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
518
DEBUG1 - 16:19:03.780334647 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
519
DEBUG1 - 16:19:03.780342682 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
520
DEBUG1 - 16:19:03.780347341 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
521
DEBUG1 - 16:19:04.780316868 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
522
DEBUG1 - 16:19:04.780322750 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
523
DEBUG1 - 16:19:04.780333556 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
524
DEBUG1 - 16:19:04.780341851 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
525
DEBUG1 - 16:19:04.780346639 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
526
DEBUG1 - 16:19:05.780315442 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
527
DEBUG1 - 16:19:05.780321405 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
528
DEBUG1 - 16:19:05.780332220 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
529
DEBUG1 - 16:19:05.780340026 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
530
DEBUG1 - 16:19:05.780344784 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
531
DEBUG1 - 16:19:05.812530335 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
532
DEBUG1 - 16:19:05.812554595 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
533
DEBUG1 - 16:19:05.812563496 [17803/17810]: Processing client command 0 (in process_client_msg() at main.c:2877)
534
DEBUG1 - 16:19:05.812567392 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
535
DEBUG2 - 16:19:05.812570310 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
536
DEBUG3 - 16:19:05.812575940 [17803/17810]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
537
DEBUG1 - 16:19:05.812578972 [17803/17810]: Setting relayd for session auto-20200114-161838 (in cmd_setup_relayd() at cmd.c:1043)
538
DEBUG2 - 16:19:05.812594052 [17803/17810]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
539
DEBUG3 - 16:19:05.812597637 [17803/17810]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
540
DEBUG2 - 16:19:05.812646459 [17803/17810]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
541
DEBUG2 - 16:19:05.812651799 [17803/17810]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
542
DEBUG3 - 16:19:05.812657523 [17803/17810]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
543
DEBUG2 - 16:19:05.812694424 [17803/17810]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
544
DEBUG2 - 16:19:05.812698798 [17803/17810]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
545
DEBUG3 - 16:19:05.812701569 [17803/17810]: UST app context 1 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
546
DEBUG2 - 16:19:05.812742780 [17803/17810]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
547
DEBUG1 - 16:19:05.812747071 [17803/17810]: Context UST 1 added to channel channel0 (in add_uctx_to_channel() at context.c:184)
548
DEBUG1 - 16:19:05.812750881 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
549
DEBUG1 - 16:19:05.812760352 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
550
DEBUG1 - 16:19:05.812763681 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
551
DEBUG1 - 16:19:05.812817845 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
552
DEBUG1 - 16:19:05.812825619 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
553
DEBUG1 - 16:19:05.812832275 [17803/17810]: Processing client command 0 (in process_client_msg() at main.c:2877)
554
DEBUG1 - 16:19:05.812834956 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
555
DEBUG2 - 16:19:05.812837307 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
556
DEBUG3 - 16:19:05.812839990 [17803/17810]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
557
DEBUG1 - 16:19:05.812842481 [17803/17810]: Setting relayd for session auto-20200114-161838 (in cmd_setup_relayd() at cmd.c:1043)
558
DEBUG2 - 16:19:05.812845675 [17803/17810]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
559
DEBUG3 - 16:19:05.812848233 [17803/17810]: UST app context 2 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
560
DEBUG2 - 16:19:05.812877212 [17803/17810]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
561
DEBUG2 - 16:19:05.812880157 [17803/17810]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
562
DEBUG3 - 16:19:05.812882447 [17803/17810]: UST app context 2 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
563
DEBUG2 - 16:19:05.812907471 [17803/17810]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
564
DEBUG2 - 16:19:05.812910222 [17803/17810]: UST app adding context to channel channel0 (in create_ust_app_channel_context() at ust-app.c:2357)
565
DEBUG3 - 16:19:05.812912551 [17803/17810]: UST app context 2 allocated (in alloc_ust_app_ctx() at ust-app.c:1146)
566
DEBUG2 - 16:19:05.812938990 [17803/17810]: UST app context handle -1 created successfully for channel channel0 (in create_ust_channel_context() at ust-app.c:1321)
567
DEBUG1 - 16:19:05.812942989 [17803/17810]: Context UST 2 added to channel channel0 (in add_uctx_to_channel() at context.c:184)
568
DEBUG1 - 16:19:05.812945592 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
569
DEBUG1 - 16:19:05.812952094 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
570
DEBUG1 - 16:19:05.812954520 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
571
DEBUG1 - 16:19:06.780316782 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
572
DEBUG1 - 16:19:06.780321716 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
573
DEBUG1 - 16:19:06.780333025 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
574
DEBUG1 - 16:19:06.780341177 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
575
DEBUG1 - 16:19:06.780346094 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
576
DEBUG1 - 16:19:07.780318808 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
577
DEBUG1 - 16:19:07.780324232 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
578
DEBUG1 - 16:19:07.780334262 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
579
DEBUG1 - 16:19:07.780341896 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
580
DEBUG1 - 16:19:07.780346684 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
581
DEBUG1 - 16:19:08.146383961 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
582
DEBUG1 - 16:19:08.146408004 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
583
DEBUG1 - 16:19:08.146416938 [17803/17810]: Processing client command 16 (in process_client_msg() at main.c:2877)
584
DEBUG1 - 16:19:08.146421035 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
585
DEBUG2 - 16:19:08.146423870 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
586
DEBUG1 - 16:19:08.146429342 [17803/17810]: Starting all UST traces (in ust_app_start_trace_all() at ust-app.c:4929)
587
DEBUG1 - 16:19:08.146431967 [17803/17810]: Clearing stream quiescent state for all ust apps (in ust_app_clear_quiescent_session() at ust-app.c:4804)
588
DEBUG2 - 16:19:08.146440999 [17803/17810]: Consumer clear quiescent channel key 1 (in consumer_clear_quiescent_channel() at consumer.c:1252)
589
DEBUG1 - 16:19:08.146461521 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
590
DEBUG1 - 16:19:08.146480942 [19216/19225]: UST consumer clear quiescent channel key 1 (in clear_quiescent_channel() at ust-consumer.c:796)
591
DEBUG1 - 16:19:08.146491747 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
592
DEBUG1 - 16:19:08.146495876 [17803/17810]: Starting tracing for ust app pid 12709 (in ust_app_start_trace() at ust-app.c:4392)
593
DEBUG3 - 16:19:08.146499989 [17803/17810]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
594
DEBUG1 - 16:19:08.146507385 [17803/17810]: Using run_as worker (in run_as() at runas.c:450)
595
DEBUG3 - 16:19:08.146552317 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
596
DEBUG3 - 16:19:08.146563340 [17803/17810]: Created hashtable size 4 at 0x12b70c0 of type 1 (in lttng_ht_new() at hashtable.c:145)
597
DEBUG3 - 16:19:08.146567386 [17803/17810]: Created hashtable size 4 at 0x12b7570 of type 0 (in lttng_ht_new() at hashtable.c:145)
598
DEBUG3 - 16:19:08.146569950 [17803/17810]: UST app channel metadata allocated (in alloc_ust_app_channel() at ust-app.c:1049)
599
DEBUG3 - 16:19:08.146573668 [17803/17810]: Session 0 found by id. (in session_find_by_id() at session.c:312)
600
DEBUG2 - 16:19:08.146576582 [17803/17810]: Asking UST consumer for channel (in ask_channel_creation() at ust-consumer.c:121)
601
DEBUG3 - 16:19:08.146582596 [17803/17810]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838/ust/uid/1000/64-bit with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
602
DEBUG1 - 16:19:08.146588947 [17803/17810]: Using run_as worker (in run_as() at runas.c:450)
603
DEBUG1 - 16:19:08.146642128 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
604
DEBUG1 - 16:19:08.146662273 [19216/19225]: Allocated channel (key 4) (in consumer_allocate_channel() at consumer.c:1031)
605
DEBUG1 - 16:19:08.146743371 [19216/19225]: Using run_as worker (in run_as() at runas.c:450)
606
DEBUG1 - 16:19:08.146808102 [19216/19225]: UST consumer add stream metadata (key: 58) with relayd id 0 (in create_ust_streams() at ust-consumer.c:347)
607
DEBUG1 - 16:19:08.146813206 [19216/19225]: Allocated metadata cache of 4096 bytes (in consumer_metadata_cache_allocate() at consumer-metadata-cache.c:198)
608
DEBUG1 - 16:19:08.146818147 [19216/19225]: UST consumer channel added (key: 4) (in add_channel() at ust-consumer.c:115)
609
DEBUG1 - 16:19:08.146823967 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
610
DEBUG2 - 16:19:08.146826842 [17803/17810]: UST ask channel 4 successfully done with 1 stream(s) (in ask_channel_creation() at ust-consumer.c:218)
611
DEBUG2 - 16:19:08.146830425 [17803/17810]: Consumer setup metadata channel key 4 (in consumer_setup_metadata() at consumer.c:1319)
612
DEBUG1 - 16:19:08.146839842 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
613
DEBUG1 - 16:19:08.146846925 [19216/19225]: UST consumer setup metadata key 4 (in setup_metadata() at ust-consumer.c:912)
614
DEBUG1 - 16:19:08.146858714 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
615
DEBUG2 - 16:19:08.146861338 [17803/17810]: UST metadata with key 4 created for app pid 12709 (in create_ust_app_metadata() at ust-app.c:3316)
616
DEBUG1 - 16:19:08.146859562 [19216/19223]: Metadata poll return from wait with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2284)
617
DEBUG3 - 16:19:08.146864880 [17803/17810]: UST app deleting channel metadata (in delete_ust_app_channel() at ust-app.c:460)
618
DEBUG1 - 16:19:08.146865577 [19216/19223]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2286)
619
DEBUG1 - 16:19:08.146870166 [19216/19223]: Adding metadata stream 58 to poll set (in consumer_thread_metadata_poll() at consumer.c:2340)
620
DEBUG1 - 16:19:08.146874943 [19216/19223]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
621
DEBUG3 - 16:19:08.146914407 [17803/17814]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
622
DEBUG3 - 16:19:08.146924364 [17803/17814]: UST app receiving notify from sock 39 (in ust_app_recv_notify() at ust-app.c:5699)
623
DEBUG2 - 16:19:08.146936626 [17803/17814]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5753)
624
DEBUG3 - 16:19:08.146951247 [17803/17814]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
625
DEBUG3 - 16:19:08.146958849 [17803/17814]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
626
DEBUG3 - 16:19:08.146971112 [17803/17814]: Append to metadata: "stream {
627
	id = 0;
628
	event.header := struct event_header_compact;
629
	packet.context := struct packet_context;
630
" (in lttng_metadata_printf() at ust-metadata.c:178)
631
DEBUG3 - 16:19:08.146974996 [17803/17814]: Append to metadata: "	event.context := struct {
632
" (in lttng_metadata_printf() at ust-metadata.c:178)
633
DEBUG3 - 16:19:08.146978075 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
634
DEBUG3 - 16:19:08.146980525 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
635
DEBUG3 - 16:19:08.146984006 [17803/17814]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _vpid;
636
" (in lttng_metadata_printf() at ust-metadata.c:178)
637
DEBUG3 - 16:19:08.146986872 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
638
DEBUG3 - 16:19:08.146989160 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
639
DEBUG3 - 16:19:08.146991969 [17803/17814]: Append to metadata: "integer { size = 64; align = 8; signed = 0; encoding = none; base = 10; } _pthread_id;
640
" (in lttng_metadata_printf() at ust-metadata.c:178)
641
DEBUG3 - 16:19:08.146994607 [17803/17814]: Append to metadata: "	};
642
" (in lttng_metadata_printf() at ust-metadata.c:178)
643
DEBUG3 - 16:19:08.146996964 [17803/17814]: Append to metadata: "};
644

    
645
" (in lttng_metadata_printf() at ust-metadata.c:178)
646
DEBUG3 - 16:19:08.146999202 [17803/17814]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5479)
647
DEBUG3 - 16:19:08.147007191 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
648
DEBUG1 - 16:19:08.153365365 [17803/17810]: Starting tracing for ust app pid 7905 (in ust_app_start_trace() at ust-app.c:4392)
649
DEBUG3 - 16:19:08.153370734 [17803/17810]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
650
DEBUG1 - 16:19:08.153376795 [17803/17810]: Using run_as worker (in run_as() at runas.c:450)
651
DEBUG3 - 16:19:08.153405825 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
652
DEBUG3 - 16:19:08.153436355 [17803/17814]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
653
DEBUG3 - 16:19:08.153440588 [17803/17814]: UST app receiving notify from sock 41 (in ust_app_recv_notify() at ust-app.c:5699)
654
DEBUG2 - 16:19:08.153444193 [17803/17814]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5753)
655
DEBUG3 - 16:19:08.153459781 [17803/17814]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
656
DEBUG3 - 16:19:08.153462912 [17803/17814]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
657
DEBUG3 - 16:19:08.153465234 [17803/17814]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5479)
658
DEBUG3 - 16:19:08.153470431 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
659
DEBUG1 - 16:19:08.159490884 [17803/17810]: Starting tracing for ust app pid 17436 (in ust_app_start_trace() at ust-app.c:4392)
660
DEBUG3 - 16:19:08.159495952 [17803/17810]: mkdir() recursive /var/lib/log/lttng_home/lttng-traces/auto-20200114-161838 with mode 504 for uid 1000 and gid 1000 (in run_as_mkdir_recursive() at runas.c:470)
661
DEBUG1 - 16:19:08.159501724 [17803/17810]: Using run_as worker (in run_as() at runas.c:450)
662
DEBUG3 - 16:19:08.159537286 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
663
DEBUG3 - 16:19:08.159577076 [17803/17814]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
664
DEBUG3 - 16:19:08.159580983 [17803/17814]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5699)
665
DEBUG2 - 16:19:08.159584382 [17803/17814]: UST app ustctl register channel received (in ust_app_recv_notify() at ust-app.c:5753)
666
DEBUG3 - 16:19:08.159591305 [17803/17814]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
667
DEBUG3 - 16:19:08.159594081 [17803/17814]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
668
DEBUG3 - 16:19:08.159596429 [17803/17814]: UST app replying to register channel key 0 with id 0, type: 1, ret: 0 (in reply_ust_register_channel() at ust-app.c:5479)
669
DEBUG3 - 16:19:08.159604303 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
670
DEBUG3 - 16:19:08.159620144 [17803/17814]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
671
DEBUG3 - 16:19:08.159622598 [17803/17814]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5699)
672
DEBUG2 - 16:19:08.159626004 [17803/17814]: UST app ustctl register event received (in ust_app_recv_notify() at ust-app.c:5719)
673
DEBUG3 - 16:19:08.159642136 [17803/17814]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
674
DEBUG3 - 16:19:08.159644904 [17803/17814]: UST registry channel finding key 0 (in ust_registry_channel_find() at ust-registry.c:796)
675
DEBUG3 - 16:19:08.159647696 [17803/17814]: UST registry creating event with event: hello_world:my_first_tracepoint, sig: int, my_integer_arg, char*, my_string_arg, id: 0, chan_objd: 2, sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:426)
676
DEBUG3 - 16:19:08.159654974 [17803/17814]: Append to metadata: "event {
677
	name = "hello_world:my_first_tracepoint";
678
	id = 0;
679
	stream_id = 0;
680
" (in lttng_metadata_printf() at ust-metadata.c:178)
681
DEBUG3 - 16:19:08.159658245 [17803/17814]: Append to metadata: "	loglevel = 13;
682
" (in lttng_metadata_printf() at ust-metadata.c:178)
683
DEBUG3 - 16:19:08.159660911 [17803/17814]: Append to metadata: "	fields := struct {
684
" (in lttng_metadata_printf() at ust-metadata.c:178)
685
DEBUG3 - 16:19:08.159663502 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
686
DEBUG3 - 16:19:08.159665908 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
687
DEBUG3 - 16:19:08.159668616 [17803/17814]: Append to metadata: "string _my_string_field;
688
" (in lttng_metadata_printf() at ust-metadata.c:178)
689
DEBUG3 - 16:19:08.159671056 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
690
DEBUG3 - 16:19:08.159673310 [17803/17814]: Append to metadata: "	" (in lttng_metadata_printf() at ust-metadata.c:178)
691
DEBUG3 - 16:19:08.159676144 [17803/17814]: Append to metadata: "integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _my_integer_field;
692
" (in lttng_metadata_printf() at ust-metadata.c:178)
693
DEBUG3 - 16:19:08.159678743 [17803/17814]: Append to metadata: "	};
694
};
695

    
696
" (in lttng_metadata_printf() at ust-metadata.c:178)
697
DEBUG3 - 16:19:08.159684742 [17803/17814]: UST registry event hello_world:my_first_tracepoint with id 0 added successfully (in add_event_ust_registry() at ust-app.c:5593)
698
DEBUG3 - 16:19:08.159690155 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
699
DEBUG1 - 16:19:08.160869072 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
700
DEBUG1 - 16:19:08.160880956 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
701
DEBUG3 - 16:19:08.160880465 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
702
DEBUG1 - 16:19:08.160899623 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
703
DEBUG3 - 16:19:08.170984393 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
704
DEBUG3 - 16:19:08.170991554 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
705
DEBUG3 - 16:19:08.181061206 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
706
DEBUG1 - 16:19:08.780316397 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
707
DEBUG1 - 16:19:08.780321427 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
708
DEBUG1 - 16:19:08.780333129 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
709
DEBUG1 - 16:19:08.780341111 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
710
DEBUG1 - 16:19:08.780345971 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
711
DEBUG1 - 16:19:09.780317007 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
712
DEBUG1 - 16:19:09.780322029 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
713
DEBUG1 - 16:19:09.780333356 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
714
DEBUG1 - 16:19:09.780341669 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
715
DEBUG1 - 16:19:09.780346433 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
716
DEBUG1 - 16:19:10.780318741 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
717
DEBUG1 - 16:19:10.780323374 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
718
DEBUG1 - 16:19:10.780333531 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
719
DEBUG1 - 16:19:10.780341210 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
720
DEBUG1 - 16:19:10.780346269 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
721
DEBUG1 - 16:19:11.780316828 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
722
DEBUG1 - 16:19:11.780322027 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
723
DEBUG1 - 16:19:11.780333335 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
724
DEBUG1 - 16:19:11.780341299 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
725
DEBUG1 - 16:19:11.780346045 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
726
DEBUG1 - 16:19:12.780316600 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
727
DEBUG1 - 16:19:12.780322381 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
728
DEBUG1 - 16:19:12.780333614 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
729
DEBUG1 - 16:19:12.780341795 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
730
DEBUG1 - 16:19:12.780346441 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
731
DEBUG1 - 16:19:13.780316196 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
732
DEBUG1 - 16:19:13.780321266 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
733
DEBUG1 - 16:19:13.780332126 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
734
DEBUG1 - 16:19:13.780339780 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
735
DEBUG1 - 16:19:13.780344403 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
736
DEBUG1 - 16:19:14.780317009 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
737
DEBUG1 - 16:19:14.780322463 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
738
DEBUG1 - 16:19:14.780332683 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
739
DEBUG1 - 16:19:14.780340659 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
740
DEBUG1 - 16:19:14.780345263 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
741
DEBUG1 - 16:19:15.575767668 [17803/17813]: Apps thread return from poll on 5 fds (in thread_manage_apps() at main.c:1480)
742
DEBUG3 - 16:19:15.575769550 [17803/17814]: [ust-thread] Manage notify return from poll on 5 fds (in ust_thread_manage_notify() at ust-thread.c:76)
743
DEBUG1 - 16:19:15.575796155 [17803/17813]: PID 17436 unregistering with sock 33 (in ust_app_unregister() at ust-app.c:3508)
744
DEBUG3 - 16:19:15.575797227 [17803/17814]: UST app receiving notify from sock 37 (in ust_app_recv_notify() at ust-app.c:5699)
745
DEBUG3 - 16:19:15.575813520 [17803/17813]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
746
DEBUG3 - 16:19:15.575815960 [17803/17814]: UST app recv notify failed. Application died (in ust_app_recv_notify() at ust-app.c:5706)
747
DEBUG2 - 16:19:15.575831536 [17803/17813]: Consumer push metadata to consumer socket 45 (in consumer_push_metadata() at consumer.c:1354)
748
DEBUG1 - 16:19:15.575834675 [17803/17814]: UST app notify socket unregister 37 (in ust_app_notify_sock_unregister() at ust-app.c:5856)
749
DEBUG3 - 16:19:15.575849665 [17803/17814]: [ust-thread] Manage notify polling (in ust_thread_manage_notify() at ust-thread.c:69)
750
DEBUG1 - 16:19:15.575858366 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
751
DEBUG1 - 16:19:15.575875667 [19216/19225]: UST consumer push metadata key 4 of len 2823 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1681)
752
DEBUG3 - 16:19:15.575887939 [17803/17813]: Consumer pushing metadata on sock 45 of len 2823 (in consumer_push_metadata() at consumer.c:1372)
753
DEBUG1 - 16:19:15.575897243 [19216/19225]: UST consumer push metadata key 4 of len 2823 (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1267)
754
DEBUG1 - 16:19:15.575910383 [19216/19225]: Writing 2823 bytes from offset 0 in metadata cache (in consumer_metadata_cache_write() at consumer-metadata-cache.c:134)
755
DEBUG1 - 16:19:15.575920360 [19216/19225]: Waiting for metadata to be flushed (in lttng_ustconsumer_recv_metadata() at ust-consumer.c:1308)
756
DEBUG1 - 16:19:15.575924071 [19216/19223]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2284)
757
DEBUG1 - 16:19:15.575929578 [19216/19223]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2286)
758
DEBUG1 - 16:19:15.575933778 [19216/19223]: Metadata available on fd 58 (in consumer_thread_metadata_poll() at consumer.c:2378)
759
DEBUG1 - 16:19:15.575939710 [19216/19223]: In UST read_subbuffer (wait_fd: 58, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
760
DEBUG1 - 16:19:15.576002913 [19216/19223]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
761
DEBUG1 - 16:19:15.576070386 [19216/19223]: In UST read_subbuffer (wait_fd: 58, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
762
DEBUG1 - 16:19:15.576075993 [19216/19223]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
763
DEBUG1 - 16:19:15.775983826 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
764
DEBUG1 - 16:19:15.776003649 [17803/17813]: Apps thread polling (in thread_manage_apps() at main.c:1473)
765
DEBUG1 - 16:19:15.780315662 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
766
DEBUG1 - 16:19:15.780320255 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
767
DEBUG1 - 16:19:15.780327933 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
768
DEBUG1 - 16:19:15.780335898 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
769
DEBUG1 - 16:19:15.780341580 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
770
DEBUG3 - 16:19:15.786035390 [17803/19226]: Call RCU deleting app PID 17436 (in delete_ust_app_rcu() at ust-app.c:944)
771
DEBUG3 - 16:19:15.786051723 [17803/19226]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
772
DEBUG3 - 16:19:15.786061502 [17803/19226]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
773
DEBUG3 - 16:19:15.786069379 [17803/19226]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:460)
774
DEBUG2 - 16:19:15.786108332 [17803/19226]: UST app pid 17436 deleted (in delete_ust_app() at ust-app.c:928)
775
DEBUG3 - 16:19:15.786107000 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
776
DEBUG3 - 16:19:15.796195199 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
777
DEBUG3 - 16:19:15.796202548 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
778
DEBUG3 - 16:19:15.806270814 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
779
DEBUG3 - 16:19:15.806276354 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
780
DEBUG3 - 16:19:15.816345178 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
781
DEBUG3 - 16:19:15.816350647 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
782
DEBUG3 - 16:19:15.826418337 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
783
DEBUG3 - 16:19:15.826423855 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
784
DEBUG3 - 16:19:15.836490495 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
785
DEBUG3 - 16:19:15.836495680 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
786
DEBUG3 - 16:19:15.846563560 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
787
DEBUG1 - 16:19:16.780316671 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
788
DEBUG1 - 16:19:16.780322104 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
789
DEBUG1 - 16:19:16.780332588 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
790
DEBUG1 - 16:19:16.780340797 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
791
DEBUG1 - 16:19:16.780345473 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
792
DEBUG1 - 16:19:17.780318147 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
793
DEBUG1 - 16:19:17.780323470 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
794
DEBUG1 - 16:19:17.780333009 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
795
DEBUG1 - 16:19:17.780343052 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
796
DEBUG1 - 16:19:17.780348148 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
797
DEBUG1 - 16:19:18.780316636 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
798
DEBUG1 - 16:19:18.780322291 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
799
DEBUG1 - 16:19:18.780332501 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
800
DEBUG1 - 16:19:18.780340866 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
801
DEBUG1 - 16:19:18.780346498 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
802
DEBUG1 - 16:19:19.780317757 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
803
DEBUG1 - 16:19:19.780323299 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
804
DEBUG1 - 16:19:19.780334582 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
805
DEBUG1 - 16:19:19.780342434 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
806
DEBUG1 - 16:19:19.780346795 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
807
DEBUG1 - 16:19:20.780318456 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
808
DEBUG1 - 16:19:20.780324328 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
809
DEBUG1 - 16:19:20.780335254 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
810
DEBUG1 - 16:19:20.780343064 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
811
DEBUG1 - 16:19:20.780348105 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
812
DEBUG1 - 16:19:21.780317204 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
813
DEBUG1 - 16:19:21.780322294 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
814
DEBUG1 - 16:19:21.780331962 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
815
DEBUG1 - 16:19:21.780340801 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
816
DEBUG1 - 16:19:21.780345525 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
817
DEBUG1 - 16:19:22.780317227 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
818
DEBUG1 - 16:19:22.780321870 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
819
DEBUG1 - 16:19:22.780333953 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
820
DEBUG1 - 16:19:22.780341736 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
821
DEBUG1 - 16:19:22.780346712 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
822
DEBUG1 - 16:19:23.780316818 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
823
DEBUG1 - 16:19:23.780326163 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
824
DEBUG1 - 16:19:23.780344078 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
825
DEBUG1 - 16:19:23.780357976 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
826
DEBUG1 - 16:19:23.780366462 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
827
DEBUG1 - 16:19:24.780317027 [19216/19221]: Sent channel monitoring sample for channel key 1, (highest = 84, lowest = 84) (in monitor_timer() at consumer-timer.c:763)
828
DEBUG1 - 16:19:24.780322518 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
829
DEBUG1 - 16:19:24.780333494 [17803/17809]: [notification-thread] Handling fd (13) activity (1) (in thread_notification() at notification-thread.c:530)
830
DEBUG1 - 16:19:24.780341949 [17803/17809]: [notification-thread] Handling channel sample for channel channel0 (key = 1) in session auto-20200114-161838 (highest usage = 84, lowest usage = 84) (in handle_notification_thread_channel_sample() at notification-thread-events.c:2209)
831
DEBUG1 - 16:19:24.780346539 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
832
DEBUG1 - 16:19:25.199055644 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
833
DEBUG1 - 16:19:25.199081635 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
834
DEBUG1 - 16:19:25.199090606 [17803/17810]: Processing client command 13 (in process_client_msg() at main.c:2877)
835
DEBUG1 - 16:19:25.199094837 [17803/17810]: Counting number of available session for UID 1000 GID 1000 (in lttng_sessions_count() at main.c:2846)
836
DEBUG1 - 16:19:25.199102457 [17803/17810]: Getting all available session for UID 1000 GID 1000 (in cmd_list_lttng_sessions() at cmd.c:3092)
837
DEBUG1 - 16:19:25.199111086 [17803/17810]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
838
DEBUG1 - 16:19:25.199120855 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
839
DEBUG1 - 16:19:25.199124070 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
840
DEBUG1 - 16:19:25.199195823 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
841
DEBUG1 - 16:19:25.199203725 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
842
DEBUG1 - 16:19:25.199210568 [17803/17810]: Processing client command 17 (in process_client_msg() at main.c:2877)
843
DEBUG1 - 16:19:25.199213178 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
844
DEBUG2 - 16:19:25.199215643 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
845
DEBUG1 - 16:19:25.199219426 [17803/17810]: Stopping all UST traces (in ust_app_stop_trace_all() at ust-app.c:4964)
846
DEBUG1 - 16:19:25.199222974 [17803/17810]: Stopping tracing for ust app pid 12709 (in ust_app_stop_trace() at ust-app.c:4502)
847
DEBUG3 - 16:19:25.199302627 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
848
DEBUG3 - 16:19:25.199309730 [17803/17810]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
849
DEBUG1 - 16:19:25.199312720 [17803/17810]: Stopping tracing for ust app pid 7905 (in ust_app_stop_trace() at ust-app.c:4502)
850
DEBUG3 - 16:19:25.199376434 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
851
DEBUG3 - 16:19:25.199380388 [17803/17810]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
852
DEBUG1 - 16:19:25.199382804 [17803/17810]: Flushing session buffers for all ust apps (in ust_app_flush_session() at ust-app.c:4659)
853
DEBUG2 - 16:19:25.199385959 [17803/17810]: Consumer flush channel key 1 (in consumer_flush_channel() at consumer.c:1220)
854
DEBUG1 - 16:19:25.199403270 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
855
DEBUG1 - 16:19:25.199420592 [19216/19225]: UST consumer flush channel key 1 (in flush_channel() at ust-consumer.c:751)
856
DEBUG1 - 16:19:25.199451508 [19216/19224]: poll num_rdy : 1 (in consumer_thread_data_poll() at consumer.c:2551)
857
DEBUG1 - 16:19:25.199461371 [19216/19224]: Normal read on fd 38 (in consumer_thread_data_poll() at consumer.c:2658)
858
DEBUG3 - 16:19:25.199464045 [17803/17810]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
859
DEBUG1 - 16:19:25.199461434 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
860
DEBUG1 - 16:19:25.199467109 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
861
DEBUG1 - 16:19:25.199466393 [19216/19224]: In UST read_subbuffer (wait_fd: 38, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
862
DEBUG1 - 16:19:25.199474527 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
863
DEBUG1 - 16:19:25.199477285 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
864
DEBUG1 - 16:19:25.199502658 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
865
DEBUG1 - 16:19:25.199509182 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
866
DEBUG1 - 16:19:25.199510938 [19216/19224]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
867
DEBUG1 - 16:19:25.199515988 [17803/17810]: Processing client command 24 (in process_client_msg() at main.c:2877)
868
DEBUG1 - 16:19:25.199518595 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
869
DEBUG2 - 16:19:25.199520901 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
870
DEBUG3 - 16:19:25.199523904 [17803/17810]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1164)
871
DEBUG1 - 16:19:25.199533217 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
872
DEBUG1 - 16:19:25.199540763 [19216/19225]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1411)
873
DEBUG1 - 16:19:25.199543519 [19216/19225]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3621)
874
DEBUG1 - 16:19:25.199552259 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
875
DEBUG1 - 16:19:25.199554848 [17803/17810]: Consumer data is  pending for session id 0 (in consumer_is_data_pending() at consumer.c:1200)
876
DEBUG1 - 16:19:25.199558469 [17803/17810]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
877
DEBUG1 - 16:19:25.199564647 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
878
DEBUG1 - 16:19:25.199567044 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
879
DEBUG1 - 16:19:25.199572098 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
880
DEBUG1 - 16:19:25.199576709 [19216/19224]: poll num_rdy : 3 (in consumer_thread_data_poll() at consumer.c:2551)
881
DEBUG1 - 16:19:25.199579022 [19216/19224]: Normal read on fd 42 (in consumer_thread_data_poll() at consumer.c:2658)
882
DEBUG1 - 16:19:25.199581485 [19216/19224]: In UST read_subbuffer (wait_fd: 42, name: channel0_2) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
883
DEBUG1 - 16:19:25.199593172 [19216/19224]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
884
DEBUG1 - 16:19:25.199612865 [19216/19224]: Normal read on fd 40 (in consumer_thread_data_poll() at consumer.c:2658)
885
DEBUG1 - 16:19:25.199615533 [19216/19224]: In UST read_subbuffer (wait_fd: 40, name: channel0_1) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
886
DEBUG1 - 16:19:25.199625137 [19216/19224]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
887
DEBUG1 - 16:19:25.199641034 [19216/19224]: Normal read on fd 44 (in consumer_thread_data_poll() at consumer.c:2658)
888
DEBUG1 - 16:19:25.199643697 [19216/19224]: In UST read_subbuffer (wait_fd: 44, name: channel0_3) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
889
DEBUG1 - 16:19:25.199653676 [19216/19224]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
890
DEBUG1 - 16:19:25.199668885 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
891
DEBUG1 - 16:19:25.399737708 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
892
DEBUG1 - 16:19:25.399759646 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
893
DEBUG1 - 16:19:25.399768824 [17803/17810]: Processing client command 24 (in process_client_msg() at main.c:2877)
894
DEBUG1 - 16:19:25.399772014 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
895
DEBUG2 - 16:19:25.399774831 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
896
DEBUG3 - 16:19:25.399779086 [17803/17810]: Consumer data pending for id 0 (in consumer_is_data_pending() at consumer.c:1164)
897
DEBUG1 - 16:19:25.399798551 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
898
DEBUG1 - 16:19:25.399814264 [19216/19225]: UST consumer data pending command for id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1411)
899
DEBUG1 - 16:19:25.399817908 [19216/19225]: Consumer data pending command on session id 0 (in consumer_data_pending() at consumer.c:3621)
900
DEBUG1 - 16:19:25.399823976 [19216/19225]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
901
DEBUG1 - 16:19:25.399828748 [19216/19225]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
902
DEBUG1 - 16:19:25.399831049 [19216/19225]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
903
DEBUG1 - 16:19:25.399833495 [19216/19225]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
904
DEBUG1 - 16:19:25.399835942 [19216/19225]: UST consumer checking data pending (in lttng_ustconsumer_data_pending() at ust-consumer.c:2742)
905
DEBUG1 - 16:19:25.399838394 [19216/19225]: UST consumer metadata pending check: contiguous 2823 vs pushed 2823 (in lttng_ustconsumer_data_pending() at ust-consumer.c:2767)
906
DEBUG1 - 16:19:25.399845498 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
907
DEBUG1 - 16:19:25.399848422 [17803/17810]: Consumer data is NOT pending for session id 0 (in consumer_is_data_pending() at consumer.c:1200)
908
DEBUG1 - 16:19:25.399853330 [17803/17810]: Sending response (size: 21, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
909
DEBUG1 - 16:19:25.399862586 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
910
DEBUG1 - 16:19:25.399866071 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
911
DEBUG1 - 16:19:25.399912809 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
912
DEBUG1 - 16:19:25.399921903 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
913
DEBUG1 - 16:19:25.399928705 [17803/17810]: Processing client command 13 (in process_client_msg() at main.c:2877)
914
DEBUG1 - 16:19:25.399931281 [17803/17810]: Counting number of available session for UID 1000 GID 1000 (in lttng_sessions_count() at main.c:2846)
915
DEBUG1 - 16:19:25.399935200 [17803/17810]: Getting all available session for UID 1000 GID 1000 (in cmd_list_lttng_sessions() at cmd.c:3092)
916
DEBUG1 - 16:19:25.399940653 [17803/17810]: Sending response (size: 4396, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
917
DEBUG1 - 16:19:25.399947612 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
918
DEBUG1 - 16:19:25.399950122 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
919
DEBUG1 - 16:19:25.399991334 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
920
DEBUG1 - 16:19:25.399998631 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
921
DEBUG1 - 16:19:25.400005651 [17803/17810]: Processing client command 11 (in process_client_msg() at main.c:2877)
922
DEBUG1 - 16:19:25.400008051 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
923
DEBUG2 - 16:19:25.400010409 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
924
DEBUG3 - 16:19:25.400016769 [17803/17810]: Listing domains found UST global domain (in cmd_list_domains() at cmd.c:2894)
925
DEBUG1 - 16:19:25.400021059 [17803/17810]: Sending response (size: 328, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
926
DEBUG1 - 16:19:25.400027593 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
927
DEBUG1 - 16:19:25.400030007 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
928
DEBUG1 - 16:19:25.400056816 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
929
DEBUG1 - 16:19:25.400063110 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
930
DEBUG1 - 16:19:25.400069627 [17803/17810]: Processing client command 10 (in process_client_msg() at main.c:2877)
931
DEBUG1 - 16:19:25.400071997 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
932
DEBUG2 - 16:19:25.400074287 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
933
DEBUG3 - 16:19:25.400077949 [17803/17810]: Consumer socket created (fd: 45) and added to output (in consumer_create_socket() at consumer.c:301)
934
DEBUG1 - 16:19:25.400080928 [17803/17810]: Setting relayd for session auto-20200114-161838 (in cmd_setup_relayd() at cmd.c:1043)
935
DEBUG3 - 16:19:25.400084315 [17803/17810]: Number of UST global channels 1 (in cmd_list_channels() at cmd.c:2977)
936
DEBUG1 - 16:19:25.400087147 [17803/17810]: Listing channels for session auto-20200114-161838 (in list_lttng_channels() at cmd.c:255)
937
DEBUG3 - 16:19:25.400090971 [17803/17810]: Consumer discarded events id 0 (in consumer_get_discarded_events() at consumer.c:1476)
938
DEBUG1 - 16:19:25.400100870 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
939
DEBUG1 - 16:19:25.400108369 [19216/19225]: UST consumer discarded events command for session id 0 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1790)
940
DEBUG1 - 16:19:25.400111568 [19216/19225]: UST consumer discarded events command for session id 0, channel key 1 (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:1817)
941
DEBUG1 - 16:19:25.400116420 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
942
DEBUG1 - 16:19:25.400119180 [17803/17810]: Consumer discarded 0 events in session id 0 (in consumer_get_discarded_events() at consumer.c:1513)
943
DEBUG1 - 16:19:25.400122808 [17803/17810]: Sending response (size: 676, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
944
DEBUG1 - 16:19:25.400129232 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
945
DEBUG1 - 16:19:25.400131602 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
946
DEBUG1 - 16:19:25.400159535 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
947
DEBUG1 - 16:19:25.400165785 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
948
DEBUG1 - 16:19:25.400172371 [17803/17810]: Processing client command 17 (in process_client_msg() at main.c:2877)
949
DEBUG1 - 16:19:25.400174819 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
950
DEBUG2 - 16:19:25.400177078 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
951
DEBUG1 - 16:19:25.400179718 [17803/17810]: Sending response (size: 20, retcode: Tracing has already been stopped (81)) (in thread_manage_clients() at main.c:4484)
952
DEBUG1 - 16:19:25.400186084 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
953
DEBUG1 - 16:19:25.400188360 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
954
DEBUG1 - 16:19:25.400212773 [17803/17810]: Wait for client response (in thread_manage_clients() at main.c:4389)
955
DEBUG1 - 16:19:25.400219008 [17803/17810]: Receiving data from client ... (in thread_manage_clients() at main.c:4434)
956
DEBUG1 - 16:19:25.400225569 [17803/17810]: Processing client command 9 (in process_client_msg() at main.c:2877)
957
DEBUG1 - 16:19:25.400228050 [17803/17810]: Getting session auto-20200114-161838 by name (in process_client_msg() at main.c:2970)
958
DEBUG2 - 16:19:25.400230319 [17803/17810]: Trying to find session by name auto-20200114-161838 (in session_find_by_name() at session.c:276)
959
DEBUG3 - 16:19:25.400233215 [17803/17810]: No kernel session when tearing down session (in kernel_destroy_session() at kernel.c:898)
960
DEBUG1 - 16:19:25.400236193 [17803/17810]: Destroy all UST traces (in ust_app_destroy_trace_all() at ust-app.c:4992)
961
DEBUG1 - 16:19:25.400239125 [17803/17810]: Destroy tracing for ust app pid 12709 (in destroy_trace() at ust-app.c:4885)
962
DEBUG3 - 16:19:25.400243369 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
963
DEBUG3 - 16:19:25.400247288 [17803/17810]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
964
DEBUG3 - 16:19:25.400250788 [17803/17810]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:460)
965
DEBUG1 - 16:19:25.400387584 [17803/17810]: Destroy tracing for ust app pid 7905 (in destroy_trace() at ust-app.c:4885)
966
DEBUG3 - 16:19:25.400392068 [17803/17810]: Buffer registry per UID find id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_find() at buffer-registry.c:203)
967
DEBUG3 - 16:19:25.400394621 [17803/17810]: No metadata to push for metadata key 4 (in ust_app_push_metadata() at ust-app.c:579)
968
DEBUG3 - 16:19:25.400397479 [17803/17810]: UST app deleting channel channel0 (in delete_ust_app_channel() at ust-app.c:460)
969
DEBUG2 - 16:19:25.400508721 [17803/17810]: Trace UST destroy session 0 (in trace_ust_destroy_session() at trace-ust.c:1163)
970
DEBUG3 - 16:19:25.400522105 [17803/17810]: Buffer registry per UID destroy with id: 0, ABI: 64, uid: 1000 (in buffer_reg_uid_destroy() at buffer-registry.c:678)
971
DEBUG3 - 16:19:25.400524502 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
972
DEBUG2 - 16:19:25.400534929 [17803/17810]: Consumer close metadata channel key 4 (in consumer_close_metadata() at consumer.c:1286)
973
DEBUG1 - 16:19:25.400554052 [19216/19225]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3204)
974
DEBUG1 - 16:19:25.400560890 [19216/19225]: UST consumer close metadata key 4 (in close_metadata() at ust-consumer.c:836)
975
DEBUG1 - 16:19:25.400564347 [19216/19225]: Closing metadata channel key 4 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2808)
976
DEBUG1 - 16:19:25.400575862 [19216/19225]: received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3220)
977
DEBUG1 - 16:19:25.400577477 [19216/19223]: Metadata poll return from wait with 2 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2284)
978
DEBUG1 - 16:19:25.400580952 [17803/17810]: Destroying session auto-20200114-161838 (in session_destroy() at session.c:331)
979
DEBUG1 - 16:19:25.400582741 [19216/19223]: Metadata event caught in thread (in consumer_thread_metadata_poll() at consumer.c:2286)
980
DEBUG1 - 16:19:25.400587013 [19216/19223]: Metadata fd 58 is hup|err. (in consumer_thread_metadata_poll() at consumer.c:2400)
981
DEBUG1 - 16:19:25.400590287 [17803/17810]: Empty ltt_sessions_ht_by_id, destroying it (in del_session_ht() at session.c:240)
982
DEBUG1 - 16:19:25.400590429 [19216/19223]: Attempting to flush and consume the UST buffers (in consumer_thread_metadata_poll() at consumer.c:2404)
983
DEBUG1 - 16:19:25.400597625 [17803/17810]: Sending response (size: 20, retcode: Success (10)) (in thread_manage_clients() at main.c:4484)
984
DEBUG1 - 16:19:25.400604836 [17803/17810]: Clean command context structure (in clean_command_ctx() at main.c:641)
985
DEBUG1 - 16:19:25.400607244 [17803/17810]: Accepting client command ... (in thread_manage_clients() at main.c:4337)
986
DEBUG1 - 16:19:25.400606990 [19216/19223]: In UST read_subbuffer (wait_fd: 58, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
987
DEBUG1 - 16:19:25.400625372 [19216/19223]: Consumer mmap write() ret 4096 (len 4096) (in lttng_consumer_on_read_subbuffer_mmap() at consumer.c:1670)
988
DEBUG1 - 16:19:25.400677267 [19216/19223]: In UST read_subbuffer (wait_fd: 58, name: metadata) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
989
DEBUG1 - 16:19:25.400688233 [19216/19223]: Closing metadata channel key 4 (in lttng_ustconsumer_close_metadata() at ust-consumer.c:2808)
990
DEBUG1 - 16:19:25.400706922 [19216/19223]: Consumer delete channel key 4 (in consumer_del_channel() at consumer.c:363)
991
DEBUG1 - 16:19:25.400745716 [19216/19223]: Metadata poll wait (in consumer_thread_metadata_poll() at consumer.c:2281)
992
DEBUG1 - 16:19:25.400758516 [19216/19691]: Destroying metadata cache (in consumer_metadata_cache_destroy() at consumer-metadata-cache.c:220)
993
DEBUG2 - 16:19:25.410392973 [17803/19226]: Trace destroy UST event hello_world:my_first_tracepoint (in trace_ust_destroy_event() at trace-ust.c:1007)
994
DEBUG2 - 16:19:25.410401414 [17803/19226]: Trace destroy UST channel channel0 (in _trace_ust_destroy_channel() at trace-ust.c:1072)
995
DEBUG3 - 16:19:25.410404954 [17803/19226]: Buffer registry session destroy (in buffer_reg_session_destroy() at buffer-registry.c:597)
996
DEBUG3 - 16:19:25.410409037 [17803/19226]: Buffer registry channel destroy with key 0 (in buffer_reg_channel_destroy() at buffer-registry.c:552)
997
DEBUG3 - 16:19:25.410411997 [17803/19226]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
998
DEBUG3 - 16:19:25.410417111 [17803/19226]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
999
DEBUG3 - 16:19:25.410420790 [17803/19226]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
1000
DEBUG3 - 16:19:25.410424326 [17803/19226]: Buffer registry stream destroy with handle -1 (in buffer_reg_stream_destroy() at buffer-registry.c:500)
1001
DEBUG1 - 16:19:25.410436735 [19216/19222]: Channel poll return from wait with 2 fd(s) (in consumer_thread_channel_poll() at consumer.c:2879)
1002
DEBUG1 - 16:19:25.410440438 [17803/19226]: Beginning of waiter wait period (in lttng_waiter_wait() at waiter.c:58)
1003
DEBUG1 - 16:19:25.410443975 [19216/19222]: Channel event caught in thread (in consumer_thread_channel_poll() at consumer.c:2881)
1004
DEBUG1 - 16:19:25.410444773 [17803/17809]: [notification-thread] Poll wait returned (1) (in thread_notification() at notification-thread.c:509)
1005
DEBUG1 - 16:19:25.410448107 [19216/19222]: Channel fd 35 is hup|err. (in consumer_thread_channel_poll() at consumer.c:3025)
1006
DEBUG1 - 16:19:25.410451982 [17803/17809]: [notification-thread] Handling fd (24) activity (1) (in thread_notification() at notification-thread.c:530)
1007
DEBUG1 - 16:19:25.410457719 [17803/17809]: [notification-thread] Received remove channel command (in handle_notification_thread_command() at notification-thread-events.c:1306)
1008
DEBUG1 - 16:19:25.410460888 [17803/17809]: [notification-thread] Removing channel key = 1 in user space domain (in handle_notification_thread_command_remove_channel() at notification-thread-events.c:889)
1009
DEBUG1 - 16:19:25.410469168 [17803/17809]: [notification-thread] Entering poll wait (in thread_notification() at notification-thread.c:507)
1010
DEBUG1 - 16:19:25.410465921 [19216/19224]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2551)
1011
DEBUG1 - 16:19:25.410469448 [17803/19226]: End of waiter wait period (in lttng_waiter_wait() at waiter.c:101)
1012
DEBUG1 - 16:19:25.410466269 [19216/19222]: Channel poll wait (in consumer_thread_channel_poll() at consumer.c:2875)
1013
DEBUG1 - 16:19:25.410488273 [19216/19224]: fd 38 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2683)
1014
DEBUG1 - 16:19:25.410506395 [19216/19224]: Polling fd 38 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1015
DEBUG1 - 16:19:25.410509190 [19216/19224]: fd 40 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2683)
1016
DEBUG1 - 16:19:25.410511743 [19216/19224]: Polling fd 40 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1017
DEBUG1 - 16:19:25.410514269 [19216/19224]: polling on 6 fd (in consumer_thread_data_poll() at consumer.c:2544)
1018
DEBUG1 - 16:19:25.410518047 [19216/19224]: poll num_rdy : 4 (in consumer_thread_data_poll() at consumer.c:2551)
1019
DEBUG1 - 16:19:25.410520395 [19216/19224]: Normal read on fd 38 (in consumer_thread_data_poll() at consumer.c:2658)
1020
DEBUG1 - 16:19:25.410522908 [19216/19224]: In UST read_subbuffer (wait_fd: 38, name: channel0_0) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
1021
DEBUG1 - 16:19:25.410526249 [19216/19224]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2570)
1022
DEBUG1 - 16:19:25.410528692 [19216/19224]: Normal read on fd 40 (in consumer_thread_data_poll() at consumer.c:2658)
1023
DEBUG1 - 16:19:25.410530931 [19216/19224]: In UST read_subbuffer (wait_fd: 40, name: channel0_1) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
1024
DEBUG1 - 16:19:25.410533448 [19216/19224]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2570)
1025
DEBUG1 - 16:19:25.410535804 [19216/19224]: fd 42 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2683)
1026
DEBUG1 - 16:19:25.410538134 [19216/19224]: Polling fd 42 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1027
DEBUG1 - 16:19:25.410540384 [19216/19224]: Polling fd 38 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1028
DEBUG1 - 16:19:25.410544709 [19216/19224]: Consumer stream destroy monitored key: 38 (in destroy_close_stream() at consumer-stream.c:265)
1029
DEBUG1 - 16:19:25.410559396 [19216/19224]: Polling fd 40 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1030
DEBUG1 - 16:19:25.410562144 [19216/19224]: Consumer stream destroy monitored key: 40 (in destroy_close_stream() at consumer-stream.c:265)
1031
DEBUG1 - 16:19:25.410569506 [19216/19224]: fd 44 is hup|err|nval. Attempting flush and read. (in consumer_thread_data_poll() at consumer.c:2683)
1032
DEBUG1 - 16:19:25.410571873 [19216/19224]: Polling fd 44 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1033
DEBUG1 - 16:19:25.410575023 [19216/19224]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
1034
DEBUG1 - 16:19:25.410578087 [19216/19224]: polling on 4 fd (in consumer_thread_data_poll() at consumer.c:2544)
1035
DEBUG1 - 16:19:25.410581009 [19216/19224]: poll num_rdy : 2 (in consumer_thread_data_poll() at consumer.c:2551)
1036
DEBUG1 - 16:19:25.410583307 [19216/19224]: Normal read on fd 42 (in consumer_thread_data_poll() at consumer.c:2658)
1037
DEBUG1 - 16:19:25.410585591 [19216/19224]: In UST read_subbuffer (wait_fd: 42, name: channel0_2) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
1038
DEBUG1 - 16:19:25.410588001 [19216/19224]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2570)
1039
DEBUG1 - 16:19:25.410590231 [19216/19224]: Normal read on fd 44 (in consumer_thread_data_poll() at consumer.c:2658)
1040
DEBUG1 - 16:19:25.410592384 [19216/19224]: In UST read_subbuffer (wait_fd: 44, name: channel0_3) (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2519)
1041
DEBUG1 - 16:19:25.410594829 [19216/19224]: Reserving sub buffer failed (everything is normal, it is due to concurrency) [ret: -11] (in lttng_ustconsumer_read_subbuffer() at ust-consumer.c:2570)
1042
DEBUG1 - 16:19:25.410597023 [19216/19224]: Polling fd 42 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1043
DEBUG1 - 16:19:25.410599553 [19216/19224]: Consumer stream destroy monitored key: 42 (in destroy_close_stream() at consumer-stream.c:265)
1044
DEBUG1 - 16:19:25.410606620 [19216/19224]: Polling fd 44 tells it has hung up. (in consumer_thread_data_poll() at consumer.c:2694)
1045
DEBUG1 - 16:19:25.410609179 [19216/19224]: Consumer stream destroy monitored key: 44 (in destroy_close_stream() at consumer-stream.c:265)
1046
DEBUG1 - 16:19:25.410616494 [19216/19224]: Consumer delete channel key 1 (in consumer_del_channel() at consumer.c:363)
1047
DEBUG3 - 16:19:25.410619622 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1048
DEBUG3 - 16:19:25.410625538 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1049
DEBUG1 - 16:19:25.410642883 [19216/19221]: Signal timer metadata thread teardown (in consumer_timer_thread() at consumer-timer.c:835)
1050
DEBUG1 - 16:19:25.410646997 [19216/19224]: Updating poll fd array (in update_poll_array() at consumer.c:1091)
1051
DEBUG1 - 16:19:25.410653102 [19216/19224]: polling on 2 fd (in consumer_thread_data_poll() at consumer.c:2544)
1052
DEBUG3 - 16:19:25.420700959 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1053
DEBUG3 - 16:19:25.420715445 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1054
DEBUG3 - 16:19:25.430790351 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1055
DEBUG3 - 16:19:25.430798497 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1056
DEBUG3 - 16:19:25.440867454 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1057
DEBUG3 - 16:19:25.440873285 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1058
DEBUG3 - 16:19:25.450941137 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1059
DEBUG3 - 16:19:25.450946771 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1060
DEBUG3 - 16:19:25.460975516 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1061
DEBUG3 - 16:19:25.460981207 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1062
DEBUG3 - 16:19:25.471037780 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1063
DEBUG3 - 16:19:25.471043189 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1064
DEBUG3 - 16:19:25.481111074 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1065
DEBUG3 - 16:19:25.481116473 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1066
DEBUG3 - 16:19:25.491183127 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1067
DEBUG3 - 16:19:25.491188564 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1068
DEBUG3 - 16:19:25.501254902 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1069
DEBUG3 - 16:19:25.501260183 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1070
DEBUG3 - 16:19:25.511328479 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1071
DEBUG3 - 16:19:25.511333768 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1072
DEBUG3 - 16:19:25.521401430 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1073
DEBUG3 - 16:19:25.521406709 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1074
DEBUG3 - 16:19:25.531476772 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1075
DEBUG3 - 16:19:25.531483023 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1076
DEBUG3 - 16:19:25.541551131 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1077
DEBUG3 - 16:19:25.541557599 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1078
DEBUG3 - 16:19:25.551625031 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1079
DEBUG3 - 16:19:25.551630150 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1080
DEBUG3 - 16:19:25.561696750 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1081
DEBUG3 - 16:19:25.561701912 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1082
DEBUG3 - 16:19:25.571768231 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
1083
DEBUG3 - 16:19:25.571774125 [17803/17806]: [ht-thread] Returning from poll on 2 fds. (in thread_ht_cleanup() at ht-cleanup.c:128)
1084
DEBUG3 - 16:19:25.581840687 [17803/17806]: [ht-thread] Polling. (in thread_ht_cleanup() at ht-cleanup.c:124)
(1-1/3)