On bookworm with linux kernel 6.1.123 ish and lttng-tools 2.13.9-1+deb12u1, we still run into lttng consumerd crash issues. The crash happens
during system shutdown when close traced applications and lttng sessions.
Error log message as below:
lttng-consumerd: consumer.c:1638: lttng_consumer_on_read_subbuffer_mmap: Assertion `stream->net_seq_idx != (uint64_t) -1ULL || stream->trace_chunk' failed.
The full verbose log message of two crash cases has been attached for reference as well, one has been modified with comments to assist analysis.
The stack trace is similar to previously reported issue, like https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=1090850,
$ gdb /usr/lib/x86_64-linux-gnu/lttng/libexec/lttng-consumerd ./lttng-consumerd.19922.1752545325.core
(gdb) bt
#0 0x00007fdbbfe7deec in ?? () from /usr/lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fdbbfe2efb2 in raise () from /usr/lib/x86_64-linux-gnu/libc.so.6
#2 0x00007fdbbfe19472 in abort () from /usr/lib/x86_64-linux-gnu/libc.so.6
#3 0x00007fdbbfe19395 in ?? () from /usr/lib/x86_64-linux-gnu/libc.so.6
#4 0x00007fdbbfe27ec2 in __assert_fail () from /usr/lib/x86_64-linux-gnu/libc.so.6
#5 0x000055c00716dccd in lttng_consumer_on_read_subbuffer_mmap (stream=0x7fdbac03a2a0, buffer=0x7fdbbd5c7ff0, padding=44) at ./src/common/consumer/consumer.c:1638
#6 0x000055c00717e5e7 in consumer_stream_consume_mmap (ctx=0x4dd2, stream=0x7fdbac03a2a0, subbuffer=0x7fdbbd5c7ff0) at ./src/common/consumer/consumer-stream.c:171
#7 0x000055c007178d31 in lttng_consumer_read_subbuffer (stream=0x7fdbac03a2a0, ctx=0x55c00e80cff0, locked_by_caller=<optimized out>) at ./src/common/consumer/consumer.c:3435
#8 0x000055c0071721ac in consumer_thread_data_poll (data=0x55c00e80cff0) at ./src/common/consumer/consumer.c:2742
#9 0x00007fdbbfe7c1f5 in ?? () from /usr/lib/x86_64-linux-gnu/libc.so.6
#10 0x00007fdbbfefc89c in ?? () from /usr/lib/x86_64-linux-gnu/libc.so.6
We've done some analysis and believed it is one bug in lttng's current implementation including upstream version.
Here's the brief description about the problem : essentially during system shutdown path, when lttng-sessiond is in the process of session destruction and rotation (the so called "quiet rotation" rotated_after_last_stop state) , lttng-consumerd still receives trace data while the relevant lttng session (in sessiond) is not active, as the consumer daemon (lttng-consumerd) operates independently with lttng-sessiond, it has no awareness of such session state change, in this case, both channel and stream’s trace_chunks in lttng-consumerd are set to NULL. Shortly after, data comes in multiple times from that stream, the first time, it triggers stream rotation and set trace_trunck to zero, once performed, the second time and eventually it leads to lttng-consumerd crash due the assert failure.
The flow is depicted in detail below:
lttng-sessiond (during shutdown path, case A):
SIGTERM signal ==> destroy_all_sessions_and_wait --> cmd_stop_trace --> set session->active = 0; --> cmd_destroy_session --> cmd_rotate_session --> if (!session->active) session_set_trace_chunk to “NULL” --> session_close_trace_chunk (chunk_being_archived)
A normal session rotation (case B):
cmd_rotate_session --> if (session->active) session_create_new_trace_chunk --> session_set_trace_chunk to “new_trace_chunk” --> consumer_create_trace_chunk --> lttng-consumerd : lttng_consumer_create_trace_chunk --> lttng_consumer_channel_set_trace_chunk (to new_trace_trunk) --> back to lttng-sessiond : session_close_trace_chunk (chunk_being_archived)
In case B: lttng_consumer_channel set to new_trace_trunk and it would keep it as is with no change to later on handle session_close_trace_chunk from lttng-sessiond.
While in case A: lttng-consumerd handles session_close_trace_chunk from lttng-sessiond as below:
lttng-consumerd : lttng_consumer_close_trace_chunk --> lttng_consumer_channel_set_trace_chunk to NULL --> channel is not deleted, set channel->trace_chunk to NULL
(refer to : src/common/consumer/consumer.c:4989)
Later on when lttng_consumerd receives data stream from the traced app, the first time, stream rotation is performed and trace_trunk is set to NULL:
lttng-consumerd : consumer_thread_data_poll --> lttng_consumer_on_read_subbuffer_mmap --> lttng_consumer_rotate_stream --> set : stream->trace_chunk = stream->chan->trace_chunk; which is NULL
In this case, when new trace data comes again in the same stream, i.e. the second time, it triggers crash:
lttng-consumerd : consumer_thread_data_poll --> lttng_consumer_on_read_subbuffer_mmap --> crash on trace_trunk check !
The flow with log message is explained as below:
===> lttng-sessiond : (cmd_rotate_session) --> session_close_trace_chunk (session 2) , and lttng-consumerd handles with lttng_consumer_close_trace_chunk (session 2)
2025-07-15T02:08:44.978637+00:00 mlx-5600-35 lttng-sessiond[19903]: DBG1 - 02:08:44.976488176 [Main]: Setting trace chunk close command to "no operation" (in lttng_trace_chunk_set_close_command() at trace-chunk.c:1797)
2025-07-15T02:08:44.978671+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976490288 [19922/19945]: Consumer rotate stream 418 (in lttng_consumer_rotate_stream() at consumer.c:4578)
2025-07-15T02:08:44.978698+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976494262 [19922/19945]: Rotate local stream: stream key 418, channel key 12 (in rotate_local_stream() at consumer.c:4538)
2025-07-15T02:08:44.978729+00:00 mlx-5600-35 lttng-sessiond[19903]: DBG1 - 02:08:44.976494702 [Main]: lttng_trace_chunk_rename_path from to (in lttng_trace_chunk_rename_path_no_lock() at trace-chunk.c:755)
2025-07-15T02:08:44.978760+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976499802 [19922/19945]: lttng_consumer_reset_stream_rotate_state for stream 418 (in lttng_consumer_reset_stream_rotate_state() at consumer.c:4523)
2025-07-15T02:08:44.978788+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976504033 [19922/19945]: Received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3298)
2025-07-15T02:08:44.978823+00:00 mlx-5600-35 lttng-sessiond[19903]: DBG1 - 02:08:44.976511172 [Main]: Sending consumer close trace chunk command: relayd_id = -1, session_id = 2, chunk_id = 0, close command = "none" (in consumer_close_trace_chunk() at consumer.c:2040)
2025-07-15T02:08:44.978857+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976524547 [19922/19945]: Incoming command on sock (in consumer_thread_sessiond_poll() at consumer.c:3282)
2025-07-15T02:08:44.978886+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976532262 [19922/19945]: Consumer close trace chunk command: relayd_id = (none), session_id = 2, chunk_id = 0, close command = none (in lttng_consumer_close_trace_chunk() at consumer.c:4937)
2025-07-15T02:08:44.978911+00:00 mlx-5600-35 lttng-sessiond[19922]: DBG1 - 02:08:44.976545471 [19922/19945]: Received command on sock (in consumer_thread_sessiond_poll() at consumer.c:3298)