From: Jonathan Rajotte Date: Tue, 19 May 2020 16:23:18 +0000 (-0400) Subject: Fix: common: abort on rotation after time manipulation X-Git-Tag: v2.11.4~1 X-Git-Url: https://git.lttng.org./?a=commitdiff_plain;h=159138d3dbee3c158b16f9c350a39659ed696745;p=lttng-tools.git Fix: common: abort on rotation after time manipulation Observed issue ============== Core dump: #0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50 #1 0x0000003eb4025548 in __GI_abort () at abort.c:79 #2 0x0000003eb402542f in __assert_fail_base (fmt=0x3eb4184ae0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x4cdee0 "(trace_chunk->timestamp_close).is_set", file=0x4cde78 "../../../lttng-tools-2.11.3/src/common/trace-chunk.c", line=903, function=0x4cf4a0 <__PRETTY_FUNCTION__.6756> "lttng_trace_chunk_move_to_completed") at assert.c:92 #3 0x0000003eb4033af2 in __GI___assert_fail (assertion=assertion@entry=0x4cdee0 "(trace_chunk->timestamp_close).is_set", file=file@entry=0x4cde78 "../../../lttng-tools-2.11.3/src/common/trace-chunk.c", line=line@entry=903, function=function@entry=0x4cf4a0 <__PRETTY_FUNCTION__.6756> "lttng_trace_chunk_move_to_completed") at assert.c:101 #4 0x000000000047f37e in lttng_trace_chunk_move_to_completed (trace_chunk=0x7fcb5c00e570) at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:903 #5 0x0000000000480755 in lttng_trace_chunk_release (ref=0x7fcb5c00e598) at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1117 #6 urcu_ref_put (release=, ref=0x7fcb5c00e598) at /usr/include/urcu/ref.h:68 #7 lttng_trace_chunk_put (chunk=0x7fcb5c00e570) at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1150 #8 0x0000000000429c22 in cmd_rotate_session (session=0x7fcb5c003ff0, rotate_return=rotate_return@entry=0x7fcb6b7ed470, quiet_rotation=quiet_rotation@entry=false) at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/cmd.c:5037 #9 0x00000000004451d7 in process_client_msg (cmd_ctx=0x7fcb5c00e760, sock=sock@entry=0x7fcb6b7fd4c0, sock_error=sock_error@entry=0x7fcb6b7fd4c4) at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/client.c:1852 #10 0x00000000004474c6 in thread_manage_clients (data=) at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/client.c:2199 #11 0x00000000004422f2 in launch_thread (data=0x4f97a0) at ../../../../lttng-tools-2.11.3/src/bin/lttng-sessiond/thread.c:75 #12 0x0000003eb4408ed4 in start_thread (arg=) at pthread_create.c:479 #13 0x0000003eb40f8e6f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Reproduction: Disable ntp/any time management mechanism. lttng create lttng enable-event -u 'lttng_ust_tracef:*' lttng start lttng rotate date --set="$(date --date='-1 hour')" lttng rotate auto-20200515-142503 Waiting for rotation to complete Error: Failed to query the state of the rotation. Logs: DEBUG1 - 12:25:28.570037987 [2660/2717]: Setting trace chunk close command to "move to completed chunk folder" (in lttng_trace_chunk_set_close_command() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1073) Error: Failed to set trace chunk close timestamp: close timestamp is before creation timestamp Error: Failed to set the close timestamp of the current trace chunk of session "auto-20200515-142503" lttng-sessiond: ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:903: lttng_trace_chunk_move_to_completed: Assertion `(trace_chunk->timestamp_close).is_set' failed. ... Aborted (core dumped) root@X10SDV-8C-TLN4F:~# DEBUG1 - 12:25:29.534263017 [2739/2739]: Releasing trace chunk registry to all trace chunks (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1414) DEBUG1 - 12:25:29.534317468 [2739/2739]: Releasing reference to trace chunk: session_id = 0chunk_id = 2, name = "20200515T122528+0000-2", status = closed (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1435) DEBUG1 - 12:25:29.534365653 [2739/2739]: Releasing reference to trace chunk: session_id = 0chunk_id = 1, name = "20200515T142520+0000-1", status = closed (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1435) DEBUG1 - 12:25:29.534400638 [2739/2739]: Released reference to 2 trace chunks in lttng_trace_chunk_registry_put_each_chunk() (in lttng_trace_chunk_registry_put_each_chunk() at ../../../lttng-tools-2.11.3/src/common/trace-chunk.c:1447) Error: 2 trace chunks are leaked by lttng-consumerd. This can be caused by an internal error of the session daemon. Cause ===== The trace_chunk->timestamp_close is not set since the result from time() is smaller than the creation timestamp. The close timestamp is smaller because the calendar system time is modified by an administrator. time() offers no monotonicity guarantee and hence is exposed to time modification of the system. The begin and close timestamps are strictly used in the name generation of the chunk/archives. Given the current usage of these timestamps validating monotonicity should not be a fatal error. Name uniqueness is provided by the chunk name suffix (auto increment). Solution ======== Do not enforce monotonicity for the begin and close timestamps but warn on unexpected return (begin > close). Known drawbacks ========= None. Signed-off-by: Jonathan Rajotte Signed-off-by: Jérémie Galarneau Change-Id: Ic4b17285d150358d1569d6821c451c243e64e9a1 --- diff --git a/src/common/trace-chunk.c b/src/common/trace-chunk.c index 944743e0b..bed6b73af 100644 --- a/src/common/trace-chunk.c +++ b/src/common/trace-chunk.c @@ -84,8 +84,14 @@ struct lttng_trace_chunk { char *name; /* An unset id means the chunk is anonymous. */ LTTNG_OPTIONAL(uint64_t) id; + + /* + * The creation and close timestamps are NOT monotonic. + * They must not be used in context were monotonicity is required. + */ LTTNG_OPTIONAL(time_t) timestamp_creation; LTTNG_OPTIONAL(time_t) timestamp_close; + LTTNG_OPTIONAL(struct chunk_credentials) credentials; LTTNG_OPTIONAL(struct lttng_directory_handle) session_output_directory; LTTNG_OPTIONAL(struct lttng_directory_handle) chunk_directory; @@ -432,11 +438,20 @@ enum lttng_trace_chunk_status lttng_trace_chunk_set_close_timestamp( status = LTTNG_TRACE_CHUNK_STATUS_INVALID_OPERATION; goto end; } + + /* + * Note: we do not enforce that the closing timestamp be greater or + * equal to the begin timestamp. These timestamps are used for + * generating the chunk name and should only be used in context where + * the monotonicity of time is not important. The source of those + * timestamps is NOT monotonic and represent the system calendar time, + * also know as the wall time. + */ if (chunk->timestamp_creation.value > close_ts) { - ERR("Failed to set trace chunk close timestamp: close timestamp is before creation timestamp"); - status = LTTNG_TRACE_CHUNK_STATUS_INVALID_ARGUMENT; - goto end; + WARN("Set trace chunk close timestamp: close timestamp is before creation timestamp, begin : %ld, close : %ld", + chunk->timestamp_creation.value, close_ts); } + LTTNG_OPTIONAL_SET(&chunk->timestamp_close, close_ts); if (!chunk->name_overridden) { free(chunk->name);