Hi Yonghong,
thanks for the additional information. Would you be willing and able to
share a coredump and/or backtrace of the crash?
I was still unable to reproduce the issue using the commands you
provided, but am interested in understanding what is happening here.
Are there any configuration options other than LTTNG_UST_DEBUG=1 set in
your environment?
Are you using urcu/lttng from packages (if so, which repo), or built
from source?
The test case I am using now:
```
# As root
$ lttng-sessiond -b
# As a non-root user which is not a member of the tracing group
$ export LTTNG_UST_DEBUG=1
$ lttng-relayd -v -b
$ lttng-sessiond -vvv --verbose-consumer -b
$ lttng create
$ lttng enable-event -u -a
```
thanks,
kienan
P.S. In the future, could you keep the lttng-dev in CC? thanks!
On 1/12/24 10:36, Yonghong Yan wrote:
Hi Kienan,
Thank you for checking. It might be just my setting problem. I will
just send it to you before we are sure it is an issue of lttng
Below is the output and steps I followed the guideline. Since I started
the relayd and sessiond in the same terminal, the verbose msg are mixed
together. I can regenerate it using two separate terminals. It is a Dell
Precision Tower box and it worked well yesterday. But I rebuilt the
system yesterday (because of NVIDIA GPU driver issue), and it then have
this issue.
*yyan7@CCI13SZWP3LWS*:*~*$ uname -a
Linux CCI13SZWP3LWS 6.5.0-14-generic #14~22.04.1-Ubuntu SMP
PREEMPT_DYNAMIC Mon Nov 20 18:15:30 UTC 2 x86_64 x86_64 x86_64 GNU/Linux
*yyan7@CCI13SZWP3LWS*:*~*$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=22.04
DISTRIB_CODENAME=jammy
DISTRIB_DESCRIPTION="Ubuntu 22.04.3 LTS"
*yyan7@CCI13SZWP3LWS*:*~*$ lttng --version
lttng (LTTng Trace Control) 2.13.10 - Nordicité
*yyan7@CCI13SZWP3LWS*:*~*$ lsmod | grep lttng
*lttng*_probe_writeback614400
*lttng*_probe_workqueue204800
*lttng*_probe_vmscan 450560
*lttng*_probe_udp122880
*lttng*_probe_timer327680
*lttng*_probe_sunrpc 204800
*lttng*_probe_statedump573440
*lttng*_probe_sock 163840
*lttng*_probe_skb163840
*lttng*_probe_signal 163840
*lttng*_probe_scsi 204800
*lttng*_probe_sched450560
*lttng*_probe_regulator204800
*lttng*_probe_rcu122880
*lttng*_probe_printk 122880
*lttng*_probe_power204800
*lttng*_probe_net327680
*lttng*_probe_napi 122880
*lttng*_probe_module 204800
*lttng*_probe_kvm368640
*lttng*_probe_jbd2 327680
*lttng*_probe_irq163840
*lttng*_probe_gpio 122880
*lttng*_probe_block409600
*lttng*_probe_asoc 368640
*lttng*_counter_client_percpu_32_modular122880
*lttng*_counter_client_percpu_64_modular122881
*lttng*_counter163842
*lttng*_counter_client_percpu_64_modular,*lttng*_counter_client_percpu_32_modular
*lttng*_ring_buffer_event_notifier_client204802
*lttng*_ring_buffer_metadata_mmap_client204800
*lttng*_ring_buffer_client_mmap_overwrite245760
*lttng*_ring_buffer_client_mmap_discard245760
*lttng*_ring_buffer_metadata_client204800
*lttng*_ring_buffer_client_overwrite245760
*lttng*_ring_buffer_client_discard245760
*lttng*_tracer 303513637
*lttng*_probe_udp,*lttng*_probe_scsi,*lttng*_probe_sched,*lttng*_probe_net,*lttng*_probe_vmscan,*lttng*_probe_writeback,*lttng*_probe_power,*lttng*_probe_rcu,*lttng*_probe_module,*lttng*_ring_buffer_client_mmap_overwrite,*lttng*_probe_statedump,*lttng*_ring_buffer_client_discard,*lttng*_probe_printk,*lttng*_probe_sock,*lttng*_probe_asoc,*lttng*_counter_client_percpu_64_modular,*lttng*_probe_irq,*lttng*_ring_buffer_client_mmap_discard,*lttng*_probe_kvm,*lttng*_probe_timer,*lttng*_ring_buffer_event_notifier_client,*lttng*_counter_client_percpu_32_modular,*lttng*_probe_workqueue,*lttng*_probe_jbd2,*lttng*_probe_signal,*lttng*_probe_skb,*lttng*_probe_block,*lttng*_probe_napi,*lttng*_ring_buffer_metadata_client,*lttng*_ring_buffer_metadata_mmap_client,*lttng*_probe_gpio,*lttng*_ring_buffer_client_overwrite,*lttng*_probe_regulator,*lttng*_probe_sunrpc
*lttng*_statedump 7536641 *lttng*_tracer
*lttng*_wrapper163847
*lttng*_statedump,*lttng*_probe_writeback,*lttng*_ring_buffer_client_mmap_overwrite,*lttng*_ring_buffer_client_discard,*lttng*_tracer,*lttng*_ring_buffer_client_mmap_discard,*lttng*_ring_buffer_client_overwrite
*lttng*_uprobes163841 *lttng*_tracer
*lttng*_clock122885
*lttng*_ring_buffer_client_mmap_overwrite,*lttng*_ring_buffer_client_discard,*lttng*_tracer,*lttng*_ring_buffer_client_mmap_discard,*lttng*_ring_buffer_client_overwrite
*lttng*_kprobes163841 *lttng*_tracer
*lttng*_lib_ring_buffer942088
*lttng*_ring_buffer_client_mmap_overwrite,*lttng*_ring_buffer_client_discard,*lttng*_tracer,*lttng*_ring_buffer_client_mmap_discard,*lttng*_ring_buffer_event_notifier_client,*lttng*_ring_buffer_metadata_client,*lttng*_ring_buffer_metadata_mmap_client,*lttng*_ring_buffer_client_overwrite
*lttng*_kretprobes 163841 *lttng*_tracer
*yyan7@CCI13SZWP3LWS*:*~*$ export LTTNG_UST_DEBUG=1
*yyan7@CCI13SZWP3LWS*:*~*$ lttng-relayd -v -b
DBG1 - 10:24:56.244818657 [3495/3495]: File descriptor count limits are
1024 (soft) and 1048576 (hard) (in set_fd_pool_size() at main.c:481)
DBG1 - 10:24:56.244870031 [3495/3495]: Signal handler set for SIGTERM,
SIGUSR1, SIGPIPE and SIGINT (in set_signal_handler() at main.c:872)
DBG1 - 10:24:56.244877662 [3495/3495]: LTTng-relayd 2.13.10 - Nordicité
(in relayd_config_log() at main.c:206)
DBG1 - 10:24:56.244885255 [3495/3495]: Clear command allowed (in main()
at main.c:4294)
DBG1 - 10:24:56.245867168 [3496/3496]: Unlinked file pool created at:
/home/yyan7/lttng-traces//.unlinked (in
lttng_unlinked_file_pool_create() at inode.c:268)
DBG1 - 10:24:56.245903674 [3496/3496]: File descriptor tracker created
with a limit of 1014 simultaneously-opened FDs (in fd_tracker_create()
at fd-tracker.c:400)
DBG1 - 10:24:56.245925508 [3496/3496]: Health check time delta in
seconds set to 20 (in health_init() at health.c:62)
DBG1 - 10:24:56.245998123 [3496/3496]: TCP inet operation timeout set to
216 sec (in lttcomm_inet_init() at inet.c:545)
DBG1 - 10:24:56.246177304 [3496/3498]: [thread] Manage health check
started (in thread_manage_health() at health-relayd.c:273)
DBG1 - 10:24:56.246222966 [3496/3499]: [thread] Relay dispatcher started
(in relay_thread_dispatcher() at main.c:1291)
DBG1 - 10:24:56.246259512 [3496/3499]: Futex n to 1 prepare done (in
futex_nto1_prepare() at futex.c:67)
DBG1 - 10:24:56.246266232 [3496/3496]: epoll set max size is 7225299 (in
compat_epoll_set_max_size() at poll.c:350)
DBG1 - 10:24:56.246272226 [3496/3499]: Woken up but nothing in the relay
command queue (in relay_thread_dispatcher() at main.c:1318)
DBG1 - 10:24:56.246224883 [3496/3500]: [thread] Relay worker started (in
relay_thread_worker() at main.c:3913)
DBG1 - 10:24:56.246332173 [3496/3501]: [thread] Relay listener started
(in relay_thread_listener() at main.c:1089)
DBG1 - 10:24:56.246489021 [3496/3498]: Health check ready (in
thread_manage_health() at health-relayd.c:364)
DBG1 - 10:24:56.246530206 [3496/3501]: Listening on Control listener
socket 13 (in relay_socket_create() at main.c:1033)
DBG1 - 10:24:56.246595589 [3496/3501]: Listening on Data listener socket
14 (in relay_socket_create() at main.c:1033)
DBG1 - 10:24:56.246623642 [3496/3501]: Listener accepting connections
(in relay_thread_listener() at main.c:1136)
DBG1 - 10:24:56.246619116 [3496/3502]: [thread] Live viewer relay
dispatcher started (in thread_dispatcher() at live.c:849)
DBG1 - 10:24:56.246652489 [3496/3502]: Futex n to 1 prepare done (in
futex_nto1_prepare() at futex.c:67)
DBG1 - 10:24:56.246662832 [3496/3502]: Woken up but nothing in the
live-viewer relay command queue (in thread_dispatcher() at live.c:876)
DBG1 - 10:24:56.246681238 [3496/3503]: [thread] Live viewer relay worker
started (in thread_worker() at live.c:2451)
DBG1 - 10:24:56.246694646 [3496/3504]: [thread] Relay live listener
started (in thread_listener() at live.c:686)
DBG1 - 10:24:56.246845536 [3496/3504]: Listening on Live listener socket
16 (in init_socket() at live.c:650)
DBG1 - 10:24:56.246891901 [3496/3504]: Listener accepting live viewers
connections (in thread_listener() at live.c:720)
*yyan7@CCI13SZWP3LWS*:*~*$ lttng-sessiond -vvv --verbose-consumer -b
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at
../../src/common/ringbuffer-clients/metadata-template.h:364)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at
../../src/common/ringbuffer-clients/template.h:826)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at
../../src/common/ringbuffer-clients/template.h:826)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at
../../src/common/ringbuffer-clients/template.h:826)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at
../../src/common/ringbuffer-clients/template.h:826)
DBG1 - 10:25:05.693401139 [Main]: [sessiond configuration]
DBG1 - 10:25:05.693458872 [Main]: version2.13.10
DBG1 - 10:25:05.693469176 [Main]: verbose: 3
DBG1 - 10:25:05.693476719 [Main]: verbose consumer:1
DBG1 - 10:25:05.693486867 [Main]: quiet mode:False
DBG1 - 10:25:05.693493268 [Main]: agent_tcp_port:[5345, 5354]
DBG1 - 10:25:05.693501264 [Main]: application socket timeout:5
DBG1 - 10:25:05.693506511 [Main]: no-kernel: False
DBG1 - 10:25:05.693511705 [Main]: background:True
DBG1 - 10:25:05.693517223 [Main]: daemonize: False
DBG1 - 10:25:05.693522427 [Main]: signal parent on start:False
DBG1 - 10:25:05.693527446 [Main]: tracing group name:tracing
DBG1 - 10:25:05.693535560 [Main]: kmod_probe_list: None
DBG1 - 10:25:05.693545390 [Main]: kmod_extra_probe_list: None
DBG1 - 10:25:05.693550476 [Main]: rundir:/home/yyan7/.lttng
DBG1 - 10:25:05.693558977 [Main]: application socket path:
/home/yyan7/.lttng/lttng-ust-sock-8
DBG1 - 10:25:05.693564632 [Main]: client socket
path:/home/yyan7/.lttng/client-lttng-sessiond
DBG1 - 10:25:05.693573771 [Main]: wait shm path: /lttng-ust-wait-8-1000
DBG1 - 10:25:05.693581196 [Main]: health socket
path:/home/yyan7/.lttng/sessiond-health
DBG1 - 10:25:05.693592417 [Main]: LTTNG_UST_CLOCK_PLUGIN:None
DBG1 - 10:25:05.693599715 [Main]: pid file path:
/home/yyan7/.lttng/lttng-sessiond.pid
DBG1 - 10:25:05.693611177 [Main]: lock file
path:/home/yyan7/.lttng/lttng-sessiond.lck
DBG1 - 10:25:05.693618666 [Main]: session load path: None
DBG1 - 10:25:05.693625291 [Main]: agent port file
path:/home/yyan7/.lttng/agent.port
DBG1 - 10:25:05.693632721 [Main]: consumerd32
path:/home/yyan7/.lttng/ustconsumerd32
DBG1 - 10:25:05.693640982 [Main]: consumerd32 bin path:Unknown
DBG1 - 10:25:05.693648470 [Main]: consumerd32 lib dir: Unknown
DBG1 - 10:25:05.693653601 [Main]: consumerd32 err unix sock
path:/home/yyan7/.lttng/ustconsumerd32/error
DBG1 - 10:25:05.693660355 [Main]: consumerd32 cmd unix sock
path:/home/yyan7/.lttng/ustconsumerd32/command
DBG1 - 10:25:05.693668191 [Main]: consumerd64
path:/home/yyan7/.lttng/ustconsumerd64
DBG1 - 10:25:05.693673539 [Main]: consumerd64 bin
path:/usr/lib/x86_64-linux-gnu/lttng/libexec/lttng-consumerd
DBG1 - 10:25:05.693682080 [Main]: consumerd64 lib dir:
/usr/lib/x86_64-linux-gnu
DBG1 - 10:25:05.693689246 [Main]: consumerd64 err unix sock
path:/home/yyan7/.lttng/ustconsumerd64/error
DBG1 - 10:25:05.693697419 [Main]: consumerd64 cmd unix sock
path:/home/yyan7/.lttng/ustconsumerd64/command
DBG1 - 10:25:05.693706980 [Main]: kconsumerd path:
/home/yyan7/.lttng/kconsumerd
DBG1 - 10:25:05.693714339 [Main]: kconsumerd err unix sock path:
/home/yyan7/.lttng/kconsumerd/error
DBG1 - 10:25:05.693724836 [Main]: kconsumerd cmd unix sock path:
/home/yyan7/.lttng/kconsumerd/command
DBG1 - 10:25:05.693736058 [Main]: Starting lttng-sessiond
{0e76c943-cc93-414c-81d5-259bf7e8d0e4} (in sessiond_uuid_log() at
main.c:1437)
DBG3 - 10:25:05.693744764 [Main]: Creating LTTng run directory:
/home/yyan7/.lttng (in create_lttng_rundir() at main.c:1069)
DBG1 - 10:25:05.696358185 [Main]: Resetting run_as worker signal
handlers to default (in reset_sighandler() at runas.c:1377)
DBG1 - 10:25:05.696480798 [Main]: run_as signal handler set for SIGTERM
and SIGINT (in set_worker_sighandlers() at runas.c:1438)
DBG1 - 10:25:05.697495897 [Main]: Health check time delta in seconds set
to 20 (in health_init() at health.c:62)
DBG1 - 10:25:05.697824357 [HT cleanup]: Entering thread entry point (in
launch_thread() at thread.c:65)
DBG1 - 10:25:05.697915191 [HT cleanup]: startup. (in thread_ht_cleanup()
at ht-cleanup.c:98)
DBG1 - 10:25:05.697964263 [HT cleanup]: epoll set max size is 7225299
(in compat_epoll_set_max_size() at poll.c:350)
DBG3 - 10:25:05.698012958 [Main]: Created hashtable size 4 at
0x5627de049140 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698041846 [Main]: Created hashtable size 4 at
0x5627de049470 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698056225 [Main]: Created hashtable size 4 at
0x5627de04bcd0 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698065318 [HT cleanup]: Polling. (in thread_ht_cleanup()
at ht-cleanup.c:122)
DBG3 - 10:25:05.698087629 [Main]: Created hashtable size 16 at
0x5627de04cf80 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698104568 [Main]: Created hashtable size 16 at
0x5627de04e230 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698117477 [Main]: Created hashtable size 16 at
0x5627de04f630 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698127087 [Main]: Created hashtable size 4 at
0x5627de050a50 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698142843 [Main]: Created hashtable size 4 at
0x5627de051d90 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG2 - 10:25:05.698158685 [Main]: Creating consumer directory:
/home/yyan7/.lttng/ustconsumerd64 (in set_consumer_sockets() at main.c:1111)
DBG2 - 10:25:05.698296819 [Main]: Creating consumer directory:
/home/yyan7/.lttng/ustconsumerd32 (in set_consumer_sockets() at main.c:1111)
DBG3 - 10:25:05.698395187 [Main]: Created hashtable size 4 at
0x5627de0530d0 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698404718 [Main]: Global buffer per UID registry
initialized (in buffer_reg_init_uid_registry() at buffer-registry.c:90)
DBG3 - 10:25:05.698427501 [Main]: Created hashtable size 4 at
0x5627de054410 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:25:05.698435763 [Main]: Global buffer per PID registry
initialized (in buffer_reg_init_pid_registry() at buffer-registry.c:219)
DBG1 - 10:25:05.698444533 [Main]: Command subsystem initialized (in
cmd_init() at cmd.c:6090)
DBG1 - 10:25:05.698503908 [Main]: '3506' written in file
/home/yyan7/.lttng/lttng-sessiond.pid (in utils_create_pid_file() at
utils.c:257)
DBG1 - 10:25:05.698588286 [Main]: TCP inet operation timeout set to 216
sec (in lttcomm_inet_init() at inet.c:545)
DBG1 - 10:25:05.698688270 [Main]: Waiting for health management thread
to be ready (in wait_until_thread_is_ready() at health.c:35)
DBG1 - 10:25:05.698771494 [Health management]: Entering thread entry
point (in launch_thread() at thread.c:65)
DBG1 - 10:25:05.698803482 [Health management]: [thread] Manage health
check started (in thread_manage_health() at health.c:65)
DBG1 - 10:25:05.698964797 [Health management]: Marking health management
thread as ready (in mark_thread_as_ready() at health.c:28)
DBG1 - 10:25:05.698981598 [Health management]: Health check ready (in
thread_manage_health() at health.c:136)
DBG1 - 10:25:05.698991179 [Main]: Health management thread is ready (in
wait_until_thread_is_ready() at health.c:37)
DBG1 - 10:25:05.699062770 [Main]: Waiting for notification thread to be
ready (in wait_until_thread_is_ready() at notification-thread.c:414)
DBG1 - 10:25:05.699151645 [Notification]: Entering thread entry point
(in launch_thread() at thread.c:65)
DBG1 - 10:25:05.699184431 [Notification]: Started notification thread
(in thread_notification() at notification-thread.c:642)
DBG1 - 10:25:05.699255526 [Notification]: Creating notification channel
UNIX socket at /home/yyan7/.lttng/sessiond-notification (in
notification_channel_socket_create() at notification-thread.c:223)
DBG1 - 10:25:05.699357295 [Notification]: Notification channel UNIX
socket created (fd = 29) (in notification_channel_socket_create() at
notification-thread.c:258)
DBG1 - 10:25:05.699387109 [Notification]: Listening on notification
channel socket (in init_thread_state() at notification-thread.c:442)
DBG1 - 10:25:05.699561257 [Notification]: Marking notification thread as
ready (in mark_thread_as_ready() at notification-thread.c:407)
DBG1 - 10:25:05.699576135 [Notification]: Entering poll wait (in
thread_notification() at notification-thread.c:668)
DBG1 - 10:25:05.699592002 [Main]: Notification thread is ready (in
wait_until_thread_is_ready() at notification-thread.c:416)
DBG1 - 10:25:05.699600050 [Action Executor]: Entering thread entry point
(in launch_thread() at thread.c:65)
DBG1 - 10:25:05.699632561 [Action Executor]: Entering work execution
loop (in action_executor_thread() at action-executor.c:761)
DBG1 - 10:25:05.699643395 [Action Executor]: No work items enqueued,
entering wait (in action_executor_thread() at action-executor.c:770)
DBG1 - 10:25:05.699750672 [Timer]: Entering thread entry point (in
launch_thread() at thread.c:65)
DBG1 - 10:25:05.699770466 [Rotation]: Entering thread entry point (in
launch_thread() at thread.c:65)
DBG1 - 10:25:05.699793428 [Main]: Created client socket (fd = 35) (in
create_client_sock() at client.c:2435)
DBG1 - 10:25:05.699796906 [Rotation]: Started rotation thread (in
thread_rotation() at rotation-thread.c:840)
DBG1 - 10:25:05.699868561 [Main]: Waiting for client thread to be ready
(in wait_thread_status() at client.c:65)
DBG1 - 10:25:05.699906378 [Client management]: Entering thread entry
point (in launch_thread() at thread.c:65)
DBG1 - 10:25:05.699943442 [Client management]: [thread] Manage client
started (in thread_manage_clients() at client.c:2468)
DBG1 - 10:25:05.700053570 [Client management]: Marking client thread's
state as running (in set_thread_status() at client.c:58)
DBG1 - 10:25:05.700067760 [Client management]: Accepting client command
... (in thread_manage_clients() at client.c:2534)
DBG1 - 10:25:05.700076510 [Main]: Client thread is ready (in
wait_thread_status() at client.c:68)
DBG1 - 10:25:05.700180769 [UST registration dispatch]: Entering thread
entry point (in launch_thread() at thread.c:65)
DBG3 - 10:25:05.700197002 [Main]: Session daemon application socket
created (fd = 41)(in create_application_socket() at register.c:71)
DBG1 - 10:25:05.700203416 [UST registration dispatch]: [thread] Dispatch
UST command started (in thread_dispatch_ust_registration() at
dispatch.c:250)
DBG1 - 10:25:05.700205198 [Notification]: Poll wait returned (1) (in
thread_notification() at notification-thread.c:670)
DBG1 - 10:25:05.700255843 [Notification]: Handling fd (29) activity (1)
(in thread_notification() at notification-thread.c:694)
DBG1 - 10:25:05.700269799 [Notification]: Handling new notification
channel client connection (in
handle_notification_thread_client_connect() at
notification-thread-events.c:3351)
DBG1 - 10:25:05.700262016 [Main]: Waiting for application registration
thread to be ready (in wait_thread_status() at register.c:131)
DBG1 - 10:25:05.700236776 [UST registration dispatch]: Futex n to 1
prepare done (in futex_nto1_prepare() at futex.c:67)
DBG1 - 10:25:05.700308063 [Notification]: Client socket (fd = 42) set as
non-blocking (in socket_set_non_blocking() at
notification-thread-events.c:3319)
DBG1 - 10:25:05.700319396 [UST registration dispatch]: Woken up but
nothing in the UST command queue (in thread_dispatch_ust_registration()
at dispatch.c:279)
DBG1 - 10:25:05.700326116 [Notification]: Added new notification channel
client socket (42) to poll set (in
handle_notification_thread_client_connect() at
notification-thread-events.c:3404)
DBG1 - 10:25:05.700372936 [Notification]: Entering poll wait (in
thread_notification() at notification-thread.c:668)
DBG1 - 10:25:05.700383798 [Notification]: Poll wait returned (1) (in
thread_notification() at notification-thread.c:670)
DBG1 - 10:25:05.700391774 [Notification]: Handling fd (42) activity (1)
(in thread_notification() at notification-thread.c:694)
DBG1 - 10:25:05.700405519 [Notification]: Entering poll wait (in
thread_notification() at notification-thread.c:668)
DBG1 - 10:25:05.700416164 [Notification]: Poll wait returned (1) (in
thread_notification() at notification-thread.c:670)
DBG1 - 10:25:05.700424451 [Notification]: Handling fd (42) activity (1)
(in thread_notification() at notification-thread.c:694)
DBG1 - 10:25:05.700439076 [Notification]: Received handshake from
client: uid = 1000, gid = 1000, protocol version = 1.1, client is
sessiond = true (in client_handle_message_handshake() at
notification-thread-events.c:3879)
DBG1 - 10:25:05.700450858 [Notification]: Send command reply (0) (in
client_send_command_reply() at notification-thread-events.c:3755)
DBG1 - 10:25:05.700460524 [Notification]: Flushing client (socket fd =
42) outgoing queue (in client_flush_outgoing_queue() at
notification-thread-events.c:3644)
DBG1 - 10:25:05.700475786 [Notification]: Entering poll wait (in
thread_notification() at notification-thread.c:668)
DBG1 - 10:25:05.700505488 [Rotation]: Entering poll wait (in
thread_rotation() at rotation-thread.c:864)
DBG1 - 10:25:05.700506992 [UST application registration]: Entering
thread entry point (in launch_thread() at thread.c:65)
DBG1 - 10:25:05.700529647 [UST application registration]: [thread]
Manage application registration started (in
thread_application_registration() at register.c:168)
DBG1 - 10:25:05.700597995 [UST application registration]: Marking
application registration thread's state as running (in
set_thread_status() at register.c:124)
DBG1 - 10:25:05.700609984 [UST application registration]: Accepting
application registration (in thread_application_registration() at
register.c:207)
DBG1 - 10:25:05.700616363 [Main]: Application registration thread is
ready (in wait_thread_status() at register.c:134)
DBG1 - 10:25:05.700627641 [Main]: Notifying applications of session
daemon state: 1 (in notify_ust_apps() at register.c:91)
DBG1 - 10:25:05.700659113 [Main]: Wait shared memory file descriptor
created successfully: path = '/lttng-ust-wait-8-1000', mmap_size = 4096,
global = false, fd = 45 (in get_wait_shm() at shm.c:133)
DBG1 - 10:25:05.700688620 [Main]: Futex wait update active 1 (in
futex_wait_update() at futex.c:55)
DBG1 - 10:25:05.700795964 [UST application management]: Entering thread
entry point (in launch_thread() at thread.c:65)
DBG1 - 10:25:05.700824549 [UST application management]: [thread] Manage
application started (in thread_application_management() at manage-apps.c:52)
DBG1 - 10:25:05.700848435 [Application notification]: Entering thread
entry point (in launch_thread() at thread.c:65)
DBG1 - 10:25:05.700866212 [Application notification]: [ust-thread]
Manage application notify command (in thread_application_notification()
at notify-apps.c:39)
DBG1 - 10:25:05.700913055 [Main]: Waiting for agent management thread to
be ready (in wait_until_thread_is_ready() at agent-thread.c:348)
DBG1 - 10:25:05.700936679 [Agent management]: Entering thread entry
point (in launch_thread() at thread.c:65)
DBG3 - 10:25:05.700952021 [Application notification]: [ust-thread]
Manage notify polling (in thread_application_notification() at
notify-apps.c:74)
DBG1 - 10:25:05.700964639 [UST application management]: Apps thread
polling (in thread_application_management() at manage-apps.c:88)
DBG1 - 10:25:05.700955328 [Agent management]: Manage agent application
registration. (in thread_agent_management() at agent-thread.c:366)
DBG3 - 10:25:05.701062072 [Agent management]: URI string:
tcp://localhost (in uri_parse() at uri.c:298)
DBG2 - 10:25:05.701282226 [Agent management]: IP address resolved to
127.0.0.1 (in set_ip_address() at uri.c:155)
DBG3 - 10:25:05.701292578 [Agent management]: URI dtype: 1, proto: 1,
host: localhost, subdir: , ctrl: 0, data: 0 (in uri_parse() at uri.c:510)
DBG3 - 10:25:05.701314205 [Agent management]: Trying to bind on port
5345 (in init_tcp_socket() at agent-thread.c:140)
DBG1 - 10:25:05.701330622 [Agent management]: Failed to bind to port
5345 since it is already in use (in init_tcp_socket() at agent-thread.c:148)
DBG3 - 10:25:05.701338804 [Agent management]: Trying to bind on port
5346 (in init_tcp_socket() at agent-thread.c:140)
DBG1 - 10:25:05.701351367 [Agent management]: Listening on TCP port 5346
and socket 54 (in init_tcp_socket() at agent-thread.c:177)
DBG1 - 10:25:05.701413970 [Agent management]: '5346' written in file
/home/yyan7/.lttng/agent.port (in utils_create_pid_file() at utils.c:257)
DBG1 - 10:25:05.701452432 [Agent management]: Marking agent management
thread as ready (in mark_thread_as_ready() at agent-thread.c:341)
DBG3 - 10:25:05.701466232 [Agent management]: Manage agent polling (in
thread_agent_management() at agent-thread.c:421)
DBG1 - 10:25:05.701544565 [Main]: Agent management thread is ready (in
wait_until_thread_is_ready() at agent-thread.c:350)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3505/3505]: LTT : ltt ring buffer client
"relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at
../../src/common/ringbuffer-clients/metadata-template.h:371)
*yyan7@CCI13SZWP3LWS*:*~*$ ps -ef | grep lttng
root 760 10 09:40 ?00:00:00 /usr/bin/*lttng*-sessiond
root 808 7600 09:40 ?00:00:00 /usr/bin/*lttng*-sessiond
yyan7 3496 10 10:24 ?00:00:00 *lttng*-relayd -v -b
yyan7 3506 10 10:25 ?00:00:00 *lttng*-sessiond -vvv --verbose-consumer -b
yyan7 350735060 10:25 ?00:00:00 *lttng*-sessiond -vvv --verbose-consumer -b
yyan7 352229970 10:25 pts/000:00:00 grep --color=auto *lttng*
*yyan7@CCI13SZWP3LWS*:*~*$ lttng create
DBG1 - 10:25:35.436359096 [Client management]: Wait for client response
(in thread_manage_clients() at client.c:2576)
DBG1 - 10:25:35.436403534 [Client management]: Receiving data from
client ... (in thread_manage_clients() at client.c:2604)
DBG1 - 10:25:35.436419086 [Client management]: Incomplete recv() from
client... continuing (in thread_manage_clients() at client.c:2608)
DBG1 - 10:25:35.436438855 [Client management]: Accepting client command
... (in thread_manage_clients() at client.c:2534)
DBG1 - 10:25:35.436458714 [Client management]: Wait for client response
(in thread_manage_clients() at client.c:2576)
DBG1 - 10:25:35.436480694 [Client management]: Receiving data from
client ... (in thread_manage_clients() at client.c:2604)
DBG1 - 10:25:35.436493760 [Client management]: Incomplete recv() from
client... continuing (in thread_manage_clients() at client.c:2608)
DBG1 - 10:25:35.436514391 [Client management]: Accepting client command
... (in thread_manage_clients() at client.c:2534)
DBG1 - 10:25:35.436522846 [Client management]: Wait for client response
(in thread_manage_clients() at client.c:2576)
DBG1 - 10:25:35.436539198 [Client management]: Receiving data from
client ... (in thread_manage_clients() at client.c:2604)
DBG1 - 10:25:35.436561992 [Client management]: Processing client command
'LTTNG_CREATE_SESSION_EXT' (49) (in process_client_msg() at client.c:1016)
DBG3 - 10:25:35.436644534 [Client management]: Created hashtable size 4
at 0x7fd67c0090b0 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG2 - 10:25:35.436670494 [Client management]: Trying to find session by
name auto-20240112-102535 (in session_find_by_name() at session.c:1143)
DBG1 - 10:25:35.436679003 [Client management]: Generated session name
"auto-20240112-102535" (in session_create() at session.c:1300)
DBG3 - 10:25:35.436693861 [Client management]: Created hashtable size 4
at 0x7fd67c00a3f0 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG1 - 10:25:35.436702475 [Client management]: Allocating
ltt_sessions_ht_by_id (in ltt_sessions_ht_alloc() at session.c:306)
DBG3 - 10:25:35.436719034 [Client management]: Created hashtable size 4
at 0x7fd67c00b730 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG1 - 10:25:35.436727024 [Client management]: Allocating
ltt_sessions_ht_by_name (in ltt_sessions_ht_alloc() at session.c:314)
DBG3 - 10:25:35.436739320 [Client management]: Created hashtable size 4
at 0x7fd67c00ca70 of type STRING (in lttng_ht_new() at hashtable.c:152)
DBG1 - 10:25:35.436750021 [Client management]: Tracing session
auto-20240112-102535 created with ID 0 by uid = 1000, gid = 1000 (in
session_create() at session.c:1348)
DBG3 - 10:25:35.436761891 [Client management]: URI string:
file:///home/yyan7/lttng-traces/auto-20240112-102535 (in uri_parse() at
uri.c:298)
DBG3 - 10:25:35.436786010 [Client management]: URI file destination:
/home/yyan7/lttng-traces/auto-20240112-102535 (in uri_parse() at uri.c:335)
DBG3 - 10:25:35.436794369 [Client management]: URI dtype: 3, proto: 0,
host: , subdir: , ctrl: 0, data: 0 (in uri_parse() at uri.c:510)
DBG2 - 10:25:35.436815787 [Client management]: Setting trace directory
path from URI to /home/yyan7/lttng-traces/auto-20240112-102535 (in
add_uri_to_consumer() at cmd.c:719)
DBG1 - 10:25:35.436861339 [Client management]: Sending response (size:
8262, retcode: Success (10)) (in thread_manage_clients() at client.c:2683)
DBG1 - 10:25:35.436885647 [Client management]: Accepting client command
... (in thread_manage_clients() at client.c:2534)
DBG1 - 10:25:35.437011410 [Client management]: Wait for client response
(in thread_manage_clients() at client.c:2576)
DBG1 - 10:25:35.437037211 [Client management]: Receiving data from
client ... (in thread_manage_clients() at client.c:2604)
DBG1 - 10:25:35.437050433 [Client management]: Incomplete recv() from
client... continuing (in thread_manage_clients() at client.c:2608)
DBG1 - 10:25:35.437065744 [Client management]: Accepting client command
... (in thread_manage_clients() at client.c:2534)
DBG1 - 10:25:35.437074955 [Client management]: Wait for client response
(in thread_manage_clients() at client.c:2576)
DBG1 - 10:25:35.437088320 [Client management]: Receiving data from
client ... (in thread_manage_clients() at client.c:2604)
DBG1 - 10:25:35.437107173 [Client management]: Processing client command
'LTTNG_LIST_SESSIONS' (13) (in process_client_msg() at client.c:1016)
DBG1 - 10:25:35.437120952 [Client management]: Counting number of
available session for UID 1000 (in lttng_sessions_count() at client.c:596)
DBG1 - 10:25:35.437130882 [Client management]: Getting all available
session for UID 1000 GID 1000 (in cmd_list_lttng_sessions() at cmd.c:3947)
DBG1 - 10:25:35.437141977 [Client management]: Sending response (size:
4409, retcode: Success (10)) (in thread_manage_clients() at client.c:2683)
DBG1 - 10:25:35.437163179 [Client management]: Accepting client command
... (in thread_manage_clients() at client.c:2534)
Session auto-20240112-102535 created.
Traces will be output to /home/yyan7/lttng-traces/auto-20240112-102535
*yyan7@CCI13SZWP3LWS*:*~*$ lttng enable-event -u -all
Error: Only one domain must be specified.
*yyan7@CCI13SZWP3LWS*:*~*$ lttng enable-event -u -a
DBG1 - 10:26:09.048651842 [Client management]: Wait for client response
(in thread_manage_clients() at client.c:2576)
DBG1 - 10:26:09.048698882 [Client management]: Receiving data from
client ... (in thread_manage_clients() at client.c:2604)
DBG1 - 10:26:09.048730037 [Client management]: Processing client command
'LTTNG_ENABLE_EVENT' (6) (in process_client_msg() at client.c:1016)
DBG1 - 10:26:09.048742929 [Client management]: Getting session
auto-20240112-102535 by name (in process_client_msg() at client.c:1133)
DBG2 - 10:26:09.048752328 [Client management]: Trying to find session by
name auto-20240112-102535 (in session_find_by_name() at session.c:1143)
DBG1 - 10:26:09.048762009 [Client management]: Creating UST session (in
create_ust_session() at client.c:510)
DBG3 - 10:26:09.048777715 [Client management]: Created hashtable size 4
at 0x7fd67c00ffd0 of type STRING (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.048801459 [Client management]: Created hashtable size 4
at 0x7fd67c011310 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.048877638 [Client management]: Created hashtable size 4
at 0x7fd67c020120 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG2 - 10:26:09.048886268 [Client management]: UST trace session create
successful (in trace_ust_create_session() at trace-ust.c:324)
DBG3 - 10:26:09.048894968 [Client management]: Copying tracing session
consumer output in UST session (in copy_session_consumer() at client.c:454)
DBG3 - 10:26:09.048930287 [Client management]: Created hashtable size 4
at 0x7fd67c0213d0 of type ULONG (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.048944965 [Client management]: Copy session consumer
subdir ust (in copy_session_consumer() at client.c:476)
DBG1 - 10:26:09.048955915 [Client management]: Spawning consumerd (in
spawn_consumerd() at client.c:204)
DBG3 - 10:26:09.048988740 [HT cleanup]: Returning from poll on 2 fds.
(in thread_ht_cleanup() at ht-cleanup.c:125)
DBG2 - 10:26:09.049819491 [Client management]: Consumer pid 3526 (in
start_consumerd() at client.c:390)
DBG2 - 10:26:09.049855514 [Client management]: Spawning consumer control
thread (in start_consumerd() at client.c:393)
DBG1 - 10:26:09.049986094 [Client management]: Waiting for consumer
management thread to be ready (in wait_until_thread_is_ready() at
manage-consumer.c:46)
DBG1 - 10:26:09.050081839 [Consumer management]: Entering thread entry
point (in launch_thread() at thread.c:65)
DBG1 - 10:26:09.050074834 [Client management]: Using 64-bit UST consumer
at: /usr/lib/x86_64-linux-gnu/lttng/libexec/lttng-consumerd (in
spawn_consumerd() at client.c:284)
DBG1 - 10:26:09.050117556 [Consumer management]: [thread] Manage
consumer started (in thread_consumer_management() at manage-consumer.c:65)
DBG3 - 10:26:09.050103089 [HT cleanup]: Polling. (in thread_ht_cleanup()
at ht-cleanup.c:122)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-metadata-mmap" init
(in lttng_ring_buffer_metadata_client_init() at
../../src/common/ringbuffer-clients/metadata-template.h:364)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-overwrite-mmap" init
(in lttng_ring_buffer_client_overwrite_init() at
../../src/common/ringbuffer-clients/template.h:826)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-overwrite-rt-mmap" init
(in lttng_ring_buffer_client_overwrite_rt_init() at
../../src/common/ringbuffer-clients/template.h:826)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-discard-mmap" init
(in lttng_ring_buffer_client_discard_init() at
../../src/common/ringbuffer-clients/template.h:826)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-discard-rt-mmap" init
(in lttng_ring_buffer_client_discard_rt_init() at
../../src/common/ringbuffer-clients/template.h:826)
DBG1 - 10:26:09.054724418 [3526/3526]: Health check time delta in
seconds set to 20 (in health_init() at health.c:62)
DBG3 - 10:26:09.054993129 [3526/3526]: Created hashtable size 4 at
0x561838919540 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.055012947 [3526/3526]: Created hashtable size 4 at
0x561838919870 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.055026387 [3526/3526]: Created hashtable size 4 at
0x561838919ba0 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.055038707 [3526/3526]: Created hashtable size 4 at
0x561838919ed0 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.055052418 [3526/3526]: Created hashtable size 4 at
0x56183891eb00 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.055070118 [3526/3526]: Created hashtable size 4 at
0x56183891fe40 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG3 - 10:26:09.055079438 [3526/3526]: Created hashtable size 4 at
0x561838921180 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG1 - 10:26:09.055131986 [3526/3526]: TCP inet operation timeout set to
216 sec (in lttcomm_inet_init() at inet.c:545)
DBG1 - 10:26:09.055169397 [3526/3526]: Connecting to error socket
/home/yyan7/.lttng/ustconsumerd64/error (in main() at lttng-consumerd.c:477)
DBG2 - 10:26:09.055307314 [Consumer management]: Receiving code from
consumer err_sock (in thread_consumer_management() at manage-consumer.c:162)
DBG1 - 10:26:09.055374257 [3526/3530]: [thread] Manage health check
started (in thread_manage_health() at health-consumerd.c:157)
DBG1 - 10:26:09.055528236 [3526/3530]: epoll set max size is 7225299 (in
compat_epoll_set_max_size() at poll.c:350)
DBG1 - 10:26:09.055617358 [3526/3530]: Health check ready (in
thread_manage_health() at health-consumerd.c:237)
DBG1 - 10:26:09.155778508 [3526/3533]: Thread metadata poll started (in
consumer_thread_metadata_poll() at consumer.c:2344)
DBG3 - 10:26:09.155827680 [3526/3532]: Created hashtable size 4 at
0x7fb838000b90 of type U64 (in lttng_ht_new() at hashtable.c:152)
DBG1 - 10:26:09.155854441 [3526/3532]: Thread channel poll started (in
consumer_thread_channel_poll() at consumer.c:2938)
DBG1 - 10:26:09.155873849 [3526/3532]: Channel main loop started (in
consumer_thread_channel_poll() at consumer.c:2953)
DBG1 - 10:26:09.155884744 [3526/3532]: Channel poll wait (in
consumer_thread_channel_poll() at consumer.c:2958)
DBG1 - 10:26:09.155910091 [3526/3533]: Metadata main loop started (in
consumer_thread_metadata_poll() at consumer.c:2360)
DBG1 - 10:26:09.155915209 [3526/3535]: Creating command socket
/home/yyan7/.lttng/ustconsumerd64/command (in
consumer_thread_sessiond_poll() at consumer.c:3201)
DBG1 - 10:26:09.155927055 [3526/3533]: Metadata poll wait (in
consumer_thread_metadata_poll() at consumer.c:2366)
DBG1 - 10:26:09.155902292 [3526/3534]: Updating poll fd array (in
update_poll_array() at consumer.c:1176)
DBG1 - 10:26:09.155992208 [3526/3534]: polling on 2 fd (in
consumer_thread_data_poll() at consumer.c:2627)
DBG1 - 10:26:09.156028520 [3526/3535]: Sending ready command to
lttng-sessiond (in consumer_thread_sessiond_poll() at consumer.c:3214)
DBG1 - 10:26:09.156117370 [3526/3535]: Connection on client_socket (in
consumer_thread_sessiond_poll() at consumer.c:3236)
DBG1 - 10:26:09.156118051 [Consumer management]: Consumer command socket
ready (fd: 61) (in thread_consumer_management() at manage-consumer.c:204)
DBG1 - 10:26:09.156134055 [Consumer management]: Consumer metadata
socket ready (fd: 62) (in thread_consumer_management() at
manage-consumer.c:205)
DBG1 - 10:26:09.156140605 [3526/3535]: Metadata connection on
client_socket (in set_metadata_socket() at consumer.c:3162)
DBG1 - 10:26:09.156159591 [Consumer management]: Sending consumer
initialization command (in consumer_init() at consumer.c:1791)
DBG1 - 10:26:09.156197563 [3526/3535]: Incoming command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3282)
DBG1 - 10:26:09.156239708 [3526/3535]: Received session daemon UUID:
0e76c943-cc93-414c-81d5-259bf7e8d0e4 (in lttng_consumer_init_command()
at consumer.c:4711)
DBG1 - 10:26:09.156260388 [3526/3535]: Received command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3298)
DBG3 - 10:26:09.156271768 [Consumer management]: Sending
SET_CHANNEL_MONITOR_PIPE command to consumer (in consumer_send_pipe() at
consumer.c:1230)
DBG1 - 10:26:09.156298833 [3526/3535]: Incoming command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3282)
DBG3 - 10:26:09.156339394 [Consumer management]: Sending channel monitor
pipe 16 to consumer on socket 61 (in consumer_send_pipe() at
consumer.c:1236)
DBG1 - 10:26:09.156373728 [3526/3535]: Received channel monitor pipe
(27) (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:2017)
DBG1 - 10:26:09.156385429 [3526/3535]: Channel monitor pipe set as
non-blocking (in lttng_ustconsumer_recv_cmd() at ust-consumer.c:2040)
DBG1 - 10:26:09.156398125 [3526/3535]: Received command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3298)
DBG2 - 10:26:09.156408026 [Consumer management]: channel monitor pipe
successfully sent (in consumer_send_pipe() at consumer.c:1244)
DBG1 - 10:26:09.156521209 [Consumer management]: Marking consumer
management thread as ready (in mark_thread_as_ready() at
manage-consumer.c:31)
DBG1 - 10:26:09.156618144 [Client management]: Consumer management
thread is ready (in wait_until_thread_is_ready() at manage-consumer.c:48)
DBG3 - 10:26:09.156649336 [Client management]: Consumer socket created
(fd: 61) and added to output (in consumer_create_socket() at consumer.c:351)
*DBG1 - 10:26:09.156661610 [Client management]: Setting relayd for
session auto-20240112-102535 (in cmd_setup_relayd() at cmd.c:1004)*
*lttng-sessiond: unix.c:185: lttcomm_recv_unix_sock: Assertion `buf'
failed.*
DBG1 - 10:26:10.269878943 [3526/3535]: Incoming command on sock (in
consumer_thread_sessiond_poll() at consumer.c:3282)
DBG1 - 10:26:10.269909824 [3526/3535]: Consumer received unexpected
message size 0 (expects 12690) (in lttng_ustconsumer_recv_cmd() at
ust-consumer.c:1401)
DBG1 - 10:26:10.269918771 [3526/3535]: Communication interrupted on
command socket (in consumer_thread_sessiond_poll() at consumer.c:3289)
DBG1 - 10:26:10.269924634 [3526/3535]: Consumer thread sessiond poll
exiting (in consumer_thread_sessiond_poll() at consumer.c:3304)
Error: Events: No session daemon is available (channel channel0, session
auto-20240112-102535)
DBG1 - 10:26:10.269945294 [3526/3535]: UST consumer closing all metadata
streams (in lttng_ustconsumer_close_all_metadata() at ust-consumer.c:3278)
DBG1 - 10:26:10.270034860 [3526/3534]: poll num_rdy : 1 (in
consumer_thread_data_poll() at consumer.c:2634)
DBG1 - 10:26:10.270051195 [3526/3532]: Channel poll return from wait
with 1 fd(s) (in consumer_thread_channel_poll() at consumer.c:2961)
DBG1 - 10:26:10.270085710 [3526/3532]: Channel event caught in thread
(in consumer_thread_channel_poll() at consumer.c:2964)
DBG1 - 10:26:10.270066746 [3526/3534]: consumer_data_pipe wake up (in
consumer_thread_data_poll() at consumer.c:2664)
DBG1 - 10:26:10.270051357 [3526/3530]: Health check thread dying (in
thread_manage_health() at health-consumerd.c:334)
DBG1 - 10:26:10.270114085 [3526/3532]: Channel poll wait (in
consumer_thread_channel_poll() at consumer.c:2958)
DBG1 - 10:26:10.270151938 [3526/3532]: Channel poll return from wait
with 0 fd(s) (in consumer_thread_channel_poll() at consumer.c:2961)
DBG1 - 10:26:10.270163529 [3526/3532]: Channel event caught in thread
(in consumer_thread_channel_poll() at consumer.c:2964)
DBG1 - 10:26:10.270115093 [3526/3534]: Consumer delete flagged data
stream (in validate_endpoint_status_data_stream() at consumer.c:2274)
DBG1 - 10:26:10.270187345 [3526/3534]: polling thread exiting (in
consumer_thread_data_poll() at consumer.c:2806)
DBG1 - 10:26:10.270226737 [3526/3533]: Metadata poll return from wait
with 1 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2368)
DBG1 - 10:26:10.270255651 [3526/3533]: Metadata event caught in thread
(in consumer_thread_metadata_poll() at consumer.c:2371)
DBG1 - 10:26:10.270264901 [3526/3533]: Metadata thread pipe hung up (in
consumer_thread_metadata_poll() at consumer.c:2426)
DBG1 - 10:26:10.270270628 [3526/3532]: Channel poll thread exiting (in
consumer_thread_channel_poll() at consumer.c:3140)
DBG1 - 10:26:10.270284048 [3526/3533]: Metadata poll wait (in
consumer_thread_metadata_poll() at consumer.c:2366)
DBG1 - 10:26:10.270292833 [3526/3533]: Metadata poll return from wait
with 0 fd(s) (in consumer_thread_metadata_poll() at consumer.c:2368)
DBG1 - 10:26:10.270300375 [3526/3533]: Metadata event caught in thread
(in consumer_thread_metadata_poll() at consumer.c:2371)
DBG1 - 10:26:10.270310033 [3526/3533]: Metadata poll thread exiting (in
consumer_thread_metadata_poll() at consumer.c:2521)
DBG1 - 10:26:10.270463392 [3526/3526]: Releasing trace chunk registry to
all trace chunks (in lttng_trace_chunk_registry_put_each_chunk() at
trace-chunk.c:2221)
DBG1 - 10:26:10.270476593 [3526/3526]: Released reference to 0 trace
chunks in lttng_trace_chunk_registry_put_each_chunk() (in
lttng_trace_chunk_registry_put_each_chunk() at trace-chunk.c:2254)
DBG1 - 10:26:10.270667263 [3526/3526]: Consumer destroying it. Closing
everything. (in lttng_consumer_destroy() at consumer.c:1546)
DBG1 - 10:26:10.270812838 [3526/3526]: Destroying run_as worker (in
run_as_destroy_worker_no_lock() at runas.c:1576)
DBG1 - 10:26:10.270818934 [3526/3526]: Closing run_as worker socket (in
run_as_destroy_worker_no_lock() at runas.c:1581)
*yyan7@CCI13SZWP3LWS*:*~*$ libringbuffer-clients[3528/3528]: LTT : ltt
ring buffer client "relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3528/3528]: LTT : ltt ring buffer client
"relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3528/3528]: LTT : ltt ring buffer client
"relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3528/3528]: LTT : ltt ring buffer client
"relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3528/3528]: LTT : ltt ring buffer client
"relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at
../../src/common/ringbuffer-clients/metadata-template.h:371)
DBG1 - 10:26:10.271345058 [3526/3526]: lttng-runas terminated with
status code 0 (in run_as_destroy_worker_no_lock() at runas.c:1601)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3526/3526]: LTT : ltt ring buffer client
"relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at
../../src/common/ringbuffer-clients/metadata-template.h:371)
DBG1 - 10:26:10.271715039 [Run-as worker]: run_as worker exiting (ret =
0) (in run_as_create_worker_no_lock() at runas.c:1526)
libringbuffer-clients[3507/3507]: LTT : ltt ring buffer client
"relay-discard-rt-mmap" exit
(in lttng_ring_buffer_client_discard_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3507/3507]: LTT : ltt ring buffer client
"relay-discard-mmap" exit
(in lttng_ring_buffer_client_discard_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3507/3507]: LTT : ltt ring buffer client
"relay-overwrite-rt-mmap" exit
(in lttng_ring_buffer_client_overwrite_rt_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3507/3507]: LTT : ltt ring buffer client
"relay-overwrite-mmap" exit
(in lttng_ring_buffer_client_overwrite_exit() at
../../src/common/ringbuffer-clients/template.h:833)
libringbuffer-clients[3507/3507]: LTT : ltt ring buffer client
"relay-metadata-mmap" exit
(in lttng_ring_buffer_metadata_client_exit() at
../../src/common/ringbuffer-clients/metadata-template.h:371)
*yyan7@CCI13SZWP3LWS*:*~*$
On Fri, Jan 12, 2024 at 10:01 AM Kienan Stewart <kstew...@efficios.com
<mailto:kstew...@efficios.com>> wrote:
Hi Yonghong,
in a brief test I'm unable to reproduce the error you see by running
the
following commands on an Ubuntu 22.04 installation with lttng-tools
2.13.10, lttng-ust 2.13.6, urcu stable-0.12, and babeltrace stable-2.0.
```
$ uname -r -v
6.5.0-14-generic #14~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Mon Nov 20
18:15:30 UTC 2
$ lttng-relayd -v -b
$ lttng-sessiond -v -b
$ lttng create
$ lttng enable-event -u --all
```
Could you please review the bug reporting guidelines at
https://lttng.org/community/ <https://lttng.org/community/> and
elaborate on the steps taken to
reproduce the issue?
thanks,
kienan
On 1/12/24 08:12, Yonghong Yan via lttng-dev wrote:
> I am not sure whether this is my setting problem or a bug with a
> more recent kernel. lttng-sessiond was killed when I tried to
"enable
> event" after a session was created. See below part of the verbose
output
> of the sessiond. It is observed on Ubuntu 22.04, kernel
6.5.0-14-generic
> #14~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC, lttng (LTTng Trace Control)
> 2.13.10 - Nordicité.
>
>
> The same version of LTTng works on another Ubuntu 22.04 machine, but
> with kernel 6.2.0-33-generic. Any suggestion on what I should try?
>
>
> Thank you
>
> Yonghong
>
>
>
> c:1016)
>
> DBG1 - 00:24:25.134138433 [Client management]: Getting session
> auto-20240112-002417 by name (in process_client_msg() at
client.c:1133)
>
> DBG1 - 00:24:25.134148894 [Client management]: Creating UST
session (in
> create_ust_session() at client.c:510)
>
> DBG1 - 00:24:25.134267958 [Client management]: Spawning consumerd
(in
> spawn_consumerd() at client.c:204)
>
> DBG1 - 00:24:25.135155823 [Client management]: Waiting for consumer
> management thread to be ready (in wait_until_thread_is_ready() at
> manage-consumer.c:46)
>
> DBG1 - 00:24:25.135247552 [Consumer management]: Entering thread
entry
> point (in launch_thread() at thread.c:65)
>
> DBG1 - 00:24:25.135293542 [Consumer management]: [thread] Manage
> consumer started (in thread_consumer_management() at
manage-consumer.c:65)
>
> DBG1 - 00:24:25.135335776 [Client management]: Using 64-bit UST
consumer
> at: /usr/lib/x86_64-linux-gnu/lttng/libexec/lttng-consumerd (in
> spawn_consumerd() at client.c:284)
>
> DBG1 - 00:24:25.240725883 [Consumer management]: Consumer command
socket
> ready (fd: 61) (in thread_consumer_management() at
manage-consumer.c:204)
>
> DBG1 - 00:24:25.240746802 [Consumer management]: Consumer metadata
> socket ready (fd: 62) (in thread_consumer_management() at
> manage-consumer.c:205)
>
> DBG1 - 00:24:25.240775318 [Consumer management]: Sending consumer
> initialization command (in consumer_init() at consumer.c:1791)
>
> DBG1 - 00:24:25.241066762 [Consumer management]: Marking consumer
> management thread as ready (in mark_thread_as_ready() at
> manage-consumer.c:31)
>
> DBG1 - 00:24:25.241100481 [Client management]: Consumer management
> thread is ready (in wait_until_thread_is_ready() at
manage-consumer.c:48)
>
> DBG1 - 00:24:25.241138386 [Client management]: Setting relayd for
> session auto-20240112-002417 (in cmd_setup_relayd() at cmd.c:1004)
>
> lttng-sessiond: unix.c:185: lttcomm_recv_unix_sock: Assertion
`buf' failed.
>
> Error: Events: No session daemon is available (channel channel0,
session
> auto-20240112-002417)
>
> [1]+Aborted (core dumped) lttng-sessiond --verbose
>
> DBG1 - 00:24:26.357769106 [Run-as worker]: run_as worker exiting
(ret =
> 0) (in run_as_create_worker_no_lock() at runas.c:1526)
>
>
>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org <mailto:lttng-dev@lists.lttng.org>
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
<https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev>
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
