From 3faa1e3d9bb6b6cd1fa370c206614af9061815be Mon Sep 17 00:00:00 2001
From: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Date: Wed, 17 May 2023 13:41:03 -0400
Subject: [PATCH] Fix: sessiond: bad fd used while rotating exiting app's buffers

Issue observed
--------------

From bug #1372:

We are observing seemingly random crashes in the LTTng consumer daemon
when tracing a C++ application with LTTng-UST. Our workload has a single
printf-like tracepoint, where each string is in the order of 1kb and the
total output is around 30MB/s.

LTTng is set up with a single session and channel enabling this
tracepoint, and we enabled rotation with a maximum size of 100MB or
every 30 seconds. We are periodically starting new traced processes and
the system runs close to 100% CPU load. This ran on an AWS
Graviton2 (ARM) instance with CentOS 7 and a 5.4 kernel, using LTTng-UST
2.13.5 and LTTng-tools 2.13.8.

The first reported error is a write to a bad file descriptor (-1),
apparently when waking up the metadata poll thread during a rotation.

Cause
-----

Inspecting the logs, we see that the metadata channel with key 574 has a
negative poll fd write end which causes the write in
consumer_metadata_wakeup_pipe to fail because of an invalid file
descriptor:

  DBG1 - 15:12:13.271001175 [6593/6605]: Waking up metadata poll thread (writing to pipe): channel name = 'metadata', channel key = 574 (in consumer_metadata_wakeup_pipe() at consumer.c:888)
  DBG3 - 15:12:13.271010093 [6593/6605]: write() fd = -1 (in consumer_metadata_wakeup_pipe() at consumer.c:892)
  PERROR - 15:12:13.271014655 [6593/6605]: Failed to write to UST metadata pipe while attempting to wake-up the metadata poll thread: Bad file descriptor (in consumer_metadata_wakeup_pipe() at consumer.c:907)
  Error: Failed to dump the metadata cache
  Error: Rotate channel failed

Meanwhile, a lot of applications seem to be unregistering. Notably, the
application associated with that metadata channel is being torn down.

Leading up to the use of a bad file descriptor, the chain of events is:

1) The "rotation" thread starts to issue "Consumer rotate channel" on
   key 574 (@ `15:12:12.865621802`), but blocks on the consumer socket
   lock. We can deduce this from the fact that thread "6605" in the
   consumer wakes up to process an unrelated command originating from the
   same socket.

   We don't see that command being issued by the session daemon, most
   likely because it occurs just before the captured logs start. All
   call sites that use this socket take the socket lock, issue their
   command, wait for a reply, and release the socket lock.

2) The application unregisters (@ `15:12:13.269722736`). The
   `registry_session`, which owns the metadata contents, is destroyed
   during `delete_ust_app_session` which is done directly as a consequence
   of the app unregistration (through a deferred RCU call), see
   `ust_app_unregister`.

   This is problematic since the consumer will request the metadata during
   the rotation of the metadata channel. In the logs, we can see that
   the "close_metadata" command blocks on the consumer socket lock.
   However, the problem occurs when the `manage-apps` acquires the lock
   before the "rotation" thread. In this instance, the "close-metadata"
   command is performed by the consumer daemon, closing the metadata
   poll file descriptor.

3) As the "close_metadata" command completes, the rotation thread
   successfully acquires the socket lock. It is not aware of the
   unregistration of the application and of the subsequent tear-down of the
   application, registry, and channels since it was already iterating on
   the application's channels.

   The consumer starts to process the channel rotation command (@
   `15:12:13.270633213`) which fails on the metadata poll fd.

Essentially, we must ensure that the lifetime of metadata
channel/streams exceeds any ongoing rotation, and prevent a rotation
from being launched when an application is being torn-down in per-PID
buffering mode.

The problem is fairly hard to reproduce as it requires threads to
wake-up in the problematic order described above. I don't have a
straight-forward reproducer for the moment.

Solution
--------

During the execution of a rotation on a per-pid session, the session
daemon iterates on all applications to rotate their data and metadata
channels.

The `ust_app` itself is correctly protected: it is owned by an RCU HT
(`ust_app_ht`) and the RCU read lock is acquired as required to protect
the lifetime of the storage of `ust_app`. However, there is no way to
lock an `ust_app` instance itself.

The rotation command assumes that if it finds the `ust_app`, it will be
able to rotate all of its channels. This isn't true: the `ust_app` can
be unregistered by the `manage-applications` thread which monitors the
application sockets for their deaths in order to teardown the
applications.

The `ust_app` doesn't directly own its channels; they are owned by an
`ust_app_session` which, itself, has a `lock` mutex. Also, the metadata
of the application is owned by the "session registry", which itself can
also be locked.

At a high-level, we want to ensure that the metadata isn't closed while
a rotation is being setup. The registry lock could provide this
guarantee. However, it currently needs to remain unlocked during the
setup of the rotation as it is used when providing the metadata to the
consumer daemon.

Taking the registry lock over the duration of the setup would result in
a deadlock like so:

- the consumer buffer consumption thread consumed a data buffer and attempts
  a metadata sync,
- the command handling thread of the consumer daemon attempts to rotate
  any stream that is already at its rotation position and locks on the
  channel lock held by the consumption thread,
- the metadata sync launches a metadata request against the session
  daemon which attempts to refresh the metadata contents through the
  command socket,
- the command handling thread never services the metadata "refresh" sent
  by the session daemon since it is locked against the same channel as
  the buffer consumption thread, resulting in a deadlock.

Instead, a different approach is required: extending the lifetime of the
application's channels over the duration of the setup of a rotation.

To do so, the `ust_app` structure (which represents a registered
application) is now reference-counted. A reference is acquired over the
duration of the rotation's setup phase. This reference transitively
holds a reference the application's tracing buffers.

Note that taking a reference doesn't prevent applications from
unregistering; it simply defers the reclamation of their buffers to the
end of the rotation setup.

As the rotation completes its setup phase, the references to the
application (and thus, its tracing buffers) are released, allowing the
reclamation of all buffering ressources.

Note that the setup phase of the rotation doesn't last long so it
shouldn't significantly change the observable behaviour in terms of
memory usage. The setup phase mostly consists in sampling the
consumption/production positions of all buffers in order to establish a
switch-over point between the old and new files.

Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I8dc1ee45dd00c85556dd70d34a3af4f3a4d4e7cb
---

--- a/src/bin/lttng-sessiond/dispatch.c
+++ b/src/bin/lttng-sessiond/dispatch.c
@@ -145,7 +145,7 @@
 					(revents & (LPOLLHUP | LPOLLERR))) {
 				cds_list_del(&wait_node->head);
 				wait_queue->count--;
-				ust_app_destroy(wait_node->app);
+				ust_app_put(wait_node->app);
 				free(wait_node);
 				/*
 				 * Silence warning of use-after-free in
--- a/src/bin/lttng-sessiond/manage-apps.c
+++ b/src/bin/lttng-sessiond/manage-apps.c
@@ -163,7 +163,7 @@
 					}
 
 					/* Socket closed on remote end. */
-					ust_app_unregister(pollfd);
+					ust_app_unregister_by_socket(pollfd);
 				} else {
 					ERR("Unexpected poll events %u for sock %d", revents, pollfd);
 					goto error;
--- a/src/bin/lttng-sessiond/session.c
+++ b/src/bin/lttng-sessiond/session.c
@@ -1416,6 +1416,7 @@
 		 */
 		session_notify_clear(session);
 	}
+
 	return ret;
 }
 
--- a/src/bin/lttng-sessiond/session.h
+++ b/src/bin/lttng-sessiond/session.h
@@ -184,6 +184,7 @@
 	 * Trigger for size-based rotations.
 	 */
 	struct lttng_trigger *rotate_trigger;
+
 	LTTNG_OPTIONAL(uint64_t) most_recent_chunk_id;
 	struct lttng_trace_chunk *current_trace_chunk;
 	struct lttng_trace_chunk *chunk_being_archived;
@@ -192,6 +193,7 @@
 	bool quiet_rotation;
 	char *last_archived_chunk_name;
 	LTTNG_OPTIONAL(uint64_t) last_archived_chunk_id;
+
 	struct lttng_dynamic_array destroy_notifiers;
 	struct lttng_dynamic_array clear_notifiers;
 	/* Session base path override. Set non-null. */
--- a/src/bin/lttng-sessiond/ust-app.c
+++ b/src/bin/lttng-sessiond/ust-app.c
@@ -3989,6 +3989,8 @@
 		goto error_free_pipe;
 	}
 
+	urcu_ref_init(&lta->ref);
+
 	lta->event_notifier_group.event_pipe = event_notifier_event_source_pipe;
 
 	lta->ppid = msg->ppid;
@@ -4227,49 +4229,32 @@
 	return ret;
 }
 
-/*
- * Unregister app by removing it from the global traceable app list and freeing
- * the data struct.
- *
- * The socket is already closed at this point so no close to sock.
- */
-void ust_app_unregister(int sock)
+static void ust_app_unregister(struct ust_app *app)
 {
-	struct ust_app *lta;
-	struct lttng_ht_node_ulong *node;
-	struct lttng_ht_iter ust_app_sock_iter;
+	int ret;
 	struct lttng_ht_iter iter;
 	struct ust_app_session *ua_sess;
-	int ret;
 
 	rcu_read_lock();
 
-	/* Get the node reference for a call_rcu */
-	lttng_ht_lookup(ust_app_ht_by_sock, (void *)((unsigned long) sock), &ust_app_sock_iter);
-	node = lttng_ht_iter_get_node_ulong(&ust_app_sock_iter);
-	assert(node);
-
-	lta = caa_container_of(node, struct ust_app, sock_n);
-	DBG("PID %d unregistering with sock %d", lta->pid, sock);
-
 	/*
 	 * For per-PID buffers, perform "push metadata" and flush all
 	 * application streams before removing app from hash tables,
 	 * ensuring proper behavior of data_pending check.
 	 * Remove sessions so they are not visible during deletion.
 	 */
-	cds_lfht_for_each_entry(lta->sessions->ht, &iter.iter, ua_sess,
+	cds_lfht_for_each_entry(app->sessions->ht, &iter.iter, ua_sess,
 			node.node) {
 		struct ust_registry_session *registry;
 
-		ret = lttng_ht_del(lta->sessions, &iter);
+		ret = lttng_ht_del(app->sessions, &iter);
 		if (ret) {
 			/* The session was already removed so scheduled for teardown. */
 			continue;
 		}
 
 		if (ua_sess->buffer_type == LTTNG_BUFFER_PER_PID) {
-			(void) ust_app_flush_app_session(lta, ua_sess);
+			(void) ust_app_flush_app_session(app, ua_sess);
 		}
 
 		/*
@@ -4310,41 +4295,63 @@
 				(void) close_metadata(registry, ua_sess->consumer);
 			}
 		}
-		cds_list_add(&ua_sess->teardown_node, &lta->teardown_head);
 
+		cds_list_add(&ua_sess->teardown_node, &app->teardown_head);
 		pthread_mutex_unlock(&ua_sess->lock);
 	}
 
-	/* Remove application from PID hash table */
-	ret = lttng_ht_del(ust_app_ht_by_sock, &ust_app_sock_iter);
-	assert(!ret);
-
 	/*
 	 * Remove application from notify hash table. The thread handling the
 	 * notify socket could have deleted the node so ignore on error because
 	 * either way it's valid. The close of that socket is handled by the
 	 * apps_notify_thread.
 	 */
-	iter.iter.node = &lta->notify_sock_n.node;
+	iter.iter.node = &app->notify_sock_n.node;
 	(void) lttng_ht_del(ust_app_ht_by_notify_sock, &iter);
 
-	/*
-	 * Ignore return value since the node might have been removed before by an
-	 * add replace during app registration because the PID can be reassigned by
-	 * the OS.
-	 */
-	iter.iter.node = &lta->pid_n.node;
+	iter.iter.node = &app->pid_n.node;
 	ret = lttng_ht_del(ust_app_ht, &iter);
 	if (ret) {
-		DBG3("Unregister app by PID %d failed. This can happen on pid reuse",
-				lta->pid);
+		WARN("Unregister app by PID %d failed", app->pid);
 	}
 
-	/* Free memory */
-	call_rcu(&lta->pid_n.head, delete_ust_app_rcu);
+	rcu_read_unlock();
+}
+
+/*
+ * Unregister app by removing it from the global traceable app list and freeing
+ * the data struct.
+ *
+ * The socket is already closed at this point, so there is no need to close it.
+ */
+void ust_app_unregister_by_socket(int sock)
+{
+	struct ust_app *app;
+	struct lttng_ht_node_ulong *node;
+	struct lttng_ht_iter ust_app_sock_iter;
+	int ret;
+
+	rcu_read_lock();
+
+	/* Get the node reference for a call_rcu */
+	lttng_ht_lookup(ust_app_ht_by_sock, (void *)((unsigned long) sock), &ust_app_sock_iter);
+	node = lttng_ht_iter_get_node_ulong(&ust_app_sock_iter);
+	assert(node);
+
+	app = caa_container_of(node, struct ust_app, sock_n);
+
+	DBG("PID %d unregistering with sock %d", app->pid, sock);
 
+	/* Remove application from socket hash table */
+	ret = lttng_ht_del(ust_app_ht_by_sock, &ust_app_sock_iter);
+	assert(!ret);
+
+	/*
+	 * The socket is closed: release its reference to the application
+	 * to trigger its eventual teardown.
+	 */
+	ust_app_put(app);
 	rcu_read_unlock();
-	return;
 }
 
 /*
@@ -4640,25 +4647,18 @@
 			 * are unregistered prior to this clean-up.
 			 */
 			assert(lttng_ht_get_count(app->token_to_event_notifier_rule_ht) == 0);
-
 			ust_app_notify_sock_unregister(app->notify_sock);
 		}
 	}
 
-	if (ust_app_ht) {
-		cds_lfht_for_each_entry(ust_app_ht->ht, &iter.iter, app, pid_n.node) {
-			ret = lttng_ht_del(ust_app_ht, &iter);
-			assert(!ret);
-			call_rcu(&app->pid_n.head, delete_ust_app_rcu);
-		}
-	}
-
 	/* Cleanup socket hash table */
 	if (ust_app_ht_by_sock) {
 		cds_lfht_for_each_entry(ust_app_ht_by_sock->ht, &iter.iter, app,
 				sock_n.node) {
 			ret = lttng_ht_del(ust_app_ht_by_sock, &iter);
 			assert(!ret);
+
+			ust_app_put(app);
 		}
 	}
 
@@ -6988,7 +6988,7 @@
 /*
  * Destroy a ust app data structure and free its memory.
  */
-void ust_app_destroy(struct ust_app *app)
+static void ust_app_destroy(struct ust_app *app)
 {
 	if (!app) {
 		return;
@@ -7415,7 +7415,7 @@
 	int ret;
 	enum lttng_error_code cmd_ret = LTTNG_OK;
 	struct lttng_ht_iter iter;
-	struct ust_app *app;
+	struct ust_app *app = NULL;
 	struct ltt_ust_session *usess = session->ust_session;
 
 	assert(usess);
@@ -7488,10 +7488,20 @@
 			struct ust_app_channel *ua_chan;
 			struct ust_app_session *ua_sess;
 			struct ust_registry_session *registry;
+			bool app_reference_taken;
+
+			app_reference_taken = ust_app_get(app);
+			if (!app_reference_taken) {
+				/* Application unregistered concurrently, skip it. */
+				DBG("Could not get application reference as it is being torn down; skipping application");
+				continue;
+			}
 
 			ua_sess = lookup_session_by_app(usess, app);
 			if (!ua_sess) {
 				/* Session not associated with this app. */
+				ust_app_put(app);
+				app = NULL;
 				continue;
 			}
 
@@ -7503,11 +7513,9 @@
 				goto error;
 			}
 
+
 			registry = get_session_registry(ua_sess);
-			if (!registry) {
-				DBG("Application session is being torn down. Skip application.");
-				continue;
-			}
+			assert(registry);
 
 			/* Rotate the data channels. */
 			cds_lfht_for_each_entry(ua_sess->channels->ht, &chan_iter.iter,
@@ -7519,9 +7527,6 @@
 						ua_sess->consumer,
 						/* is_metadata_channel */ false);
 				if (ret < 0) {
-					/* Per-PID buffer and application going away. */
-					if (ret == -LTTNG_ERR_CHAN_NOT_FOUND)
-						continue;
 					cmd_ret = LTTNG_ERR_ROTATION_FAIL_CONSUMER;
 					goto error;
 				}
@@ -7536,13 +7541,15 @@
 					ua_sess->consumer,
 					/* is_metadata_channel */ true);
 			if (ret < 0) {
-				/* Per-PID buffer and application going away. */
-				if (ret == -LTTNG_ERR_CHAN_NOT_FOUND)
-					continue;
 				cmd_ret = LTTNG_ERR_ROTATION_FAIL_CONSUMER;
 				goto error;
 			}
+
+			ust_app_put(app);
+			app = NULL;
 		}
+
+		app = NULL;
 		break;
 	}
 	default:
@@ -7553,6 +7560,7 @@
 	cmd_ret = LTTNG_OK;
 
 error:
+	ust_app_put(app);
 	rcu_read_unlock();
 	return cmd_ret;
 }
@@ -7934,3 +7942,26 @@
 	rcu_read_unlock();
 	return ret;
 }
+
+static void ust_app_release(struct urcu_ref *ref)
+{
+	struct ust_app *app = container_of(ref, struct ust_app, ref);
+
+	ust_app_unregister(app);
+	ust_app_destroy(app);
+}
+
+bool ust_app_get(struct ust_app *app)
+{
+	assert(app);
+	return urcu_ref_get_unless_zero(&app->ref);
+}
+
+void ust_app_put(struct ust_app *app)
+{
+	if (!app) {
+		return;
+	}
+
+	urcu_ref_put(&app->ref, ust_app_release);
+}
--- a/src/bin/lttng-sessiond/ust-app.h
+++ b/src/bin/lttng-sessiond/ust-app.h
@@ -10,6 +10,7 @@
 #define _LTT_UST_APP_H
 
 #include <stdint.h>
+#include <urcu/ref.h>
 
 #include <common/index-allocator.h>
 #include <common/uuid.h>
@@ -248,6 +249,12 @@
  * and a linked list is kept of all running traceable app.
  */
 struct ust_app {
+	/*
+	 * The lifetime of 'sock' holds a reference to the application; the
+	 * application management thread will release a reference to the
+	 * application if the application dies.
+	 */
+	struct urcu_ref ref;
 	int sock;
 	pthread_mutex_t sock_lock;	/* Protects sock protocol. */
 
@@ -337,7 +344,7 @@
 int ust_app_register(struct ust_register_msg *msg, int sock);
 int ust_app_register_done(struct ust_app *app);
 int ust_app_version(struct ust_app *app);
-void ust_app_unregister(int sock);
+void ust_app_unregister_by_socket(int sock);
 int ust_app_start_trace_all(struct ltt_ust_session *usess);
 int ust_app_stop_trace_all(struct ltt_ust_session *usess);
 int ust_app_destroy_trace_all(struct ltt_ust_session *usess);
@@ -371,7 +378,6 @@
 void ust_app_notify_sock_unregister(int sock);
 ssize_t ust_app_push_metadata(struct ust_registry_session *registry,
 		struct consumer_socket *socket, int send_zero_data);
-void ust_app_destroy(struct ust_app *app);
 enum lttng_error_code ust_app_snapshot_record(
 		const struct ltt_ust_session *usess,
 		const struct consumer_output *output, int wait,
@@ -407,6 +413,9 @@
 bool ust_app_supports_notifiers(const struct ust_app *app);
 bool ust_app_supports_counters(const struct ust_app *app);
 
+bool ust_app_get(struct ust_app *app);
+void ust_app_put(struct ust_app *app);
+
 #else /* HAVE_LIBLTTNG_UST_CTL */
 
 static inline
@@ -455,7 +464,7 @@
 	return -ENOSYS;
 }
 static inline
-void ust_app_unregister(int sock)
+void ust_app_unregister_by_socket(int sock)
 {
 }
 static inline
@@ -572,11 +581,6 @@
 	return 0;
 }
 static inline
-void ust_app_destroy(struct ust_app *app)
-{
-	return;
-}
-static inline
 enum lttng_error_code ust_app_snapshot_record(struct ltt_ust_session *usess,
 		const struct consumer_output *output, int wait, uint64_t max_stream_size)
 {
@@ -678,6 +682,16 @@
 	return 0;
 }
 
+static inline
+void ust_app_get(struct ust_app *app)
+{
+}
+
+static inline
+void ust_app_put(struct ust_app *app)
+{
+}
+
 #endif /* HAVE_LIBLTTNG_UST_CTL */
 
 #endif /* _LTT_UST_APP_H */