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=<optimized out>, 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=<optimized out>) 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=<optimized out>) 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 <jonathan.rajotte-julien@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ic4b17285d150358d1569d6821c451c243e64e9a1

diff --git a/src/common/trace-chunk.c b/src/common/trace-chunk.c
index 32792926928d6abb6ebed749460e3a970307c2f3..313d49375d6ed0e03cec04af05619aa961b545b2 100644 (file)
--- a/src/common/trace-chunk.c
+++ b/src/common/trace-chunk.c
@@ -97,8 +97,14 @@ struct lttng_trace_chunk {
        char *path;
        /* 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;
        struct lttng_directory_handle *session_output_directory;
        struct lttng_directory_handle *chunk_directory;
@@ -599,11 +605,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);