From a7db814eb92cdd2d5a19f37677f3ba7228655758 Mon Sep 17 00:00:00 2001 From: =?utf8?q?J=C3=A9r=C3=A9mie=20Galarneau?= Date: Wed, 17 May 2023 13:41:03 -0400 Subject: [PATCH] Fix: sessiond: bad fd used while rotating exiting app's buffers MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit 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 Change-Id: I8dc1ee45dd00c85556dd70d34a3af4f3a4d4e7cb --- src/bin/lttng-sessiond/dispatch.cpp | 3 +- src/bin/lttng-sessiond/manage-apps.cpp | 4 +- src/bin/lttng-sessiond/ust-app.cpp | 182 ++++++++++++++----------- src/bin/lttng-sessiond/ust-app.hpp | 31 +++-- 4 files changed, 129 insertions(+), 91 deletions(-) diff --git a/src/bin/lttng-sessiond/dispatch.cpp b/src/bin/lttng-sessiond/dispatch.cpp index 811cec0d9..141d8b4d0 100644 --- a/src/bin/lttng-sessiond/dispatch.cpp +++ b/src/bin/lttng-sessiond/dispatch.cpp @@ -140,8 +140,9 @@ static void sanitize_wait_queue(struct ust_reg_wait_queue *wait_queue) if (pollfd == wait_node->app->sock && (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 * cds_list_for_each_entry_safe which uses diff --git a/src/bin/lttng-sessiond/manage-apps.cpp b/src/bin/lttng-sessiond/manage-apps.cpp index 68e70676a..ef55b452e 100644 --- a/src/bin/lttng-sessiond/manage-apps.cpp +++ b/src/bin/lttng-sessiond/manage-apps.cpp @@ -37,7 +37,7 @@ static void cleanup_application_management_thread(void *data) * * At that point, it flushes the data (tracing and metadata) associated * with this application and tears down ust app sessions and other - * associated data structures through ust_app_unregister(). + * associated data structures through ust_app_unregister_by_socket(). * * Note that this thread never sends commands to the applications * through the command sockets; it merely listens for hang-ups @@ -167,7 +167,7 @@ static void *thread_application_management(void *data) } /* 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, diff --git a/src/bin/lttng-sessiond/ust-app.cpp b/src/bin/lttng-sessiond/ust-app.cpp index f626ee22a..82430db77 100644 --- a/src/bin/lttng-sessiond/ust-app.cpp +++ b/src/bin/lttng-sessiond/ust-app.cpp @@ -32,6 +32,7 @@ #include #include #include +#include #include #include @@ -65,7 +66,7 @@ struct lttng_ht *ust_app_ht; struct lttng_ht *ust_app_ht_by_sock; struct lttng_ht *ust_app_ht_by_notify_sock; -static int ust_app_flush_app_session(struct ust_app *app, struct ust_app_session *ua_sess); +static int ust_app_flush_app_session(ust_app& app, ust_app_session& ua_sess); /* Next available channel key. Access under next_channel_key_lock. */ static uint64_t _next_channel_key; @@ -4070,6 +4071,8 @@ struct ust_app *ust_app_create(struct ust_register_msg *msg, int sock) goto error_free_pipe; } + urcu_ref_init(<a->ref); + lta->event_notifier_group.event_pipe = event_notifier_event_source_pipe; lta->ppid = msg->ppid; @@ -4327,56 +4330,37 @@ error: 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(ust_app& app) { - struct ust_app *lta; - struct lttng_ht_node_ulong *node; - struct lttng_ht_iter ust_app_sock_iter; struct lttng_ht_iter iter; struct ust_app_session *ua_sess; - int ret; lttng::urcu::read_lock_guard 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); - LTTNG_ASSERT(node); - - lta = lttng::utils::container_of(node, &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, node.node) { - ret = lttng_ht_del(lta->sessions, &iter); - if (ret) { + cds_lfht_for_each_entry (app.sessions->ht, &iter.iter, ua_sess, node.node) { + const auto del_ret = lttng_ht_del(app.sessions, &iter); + if (del_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); } /* * Add session to list for teardown. This is safe since at this point we * are the only one using this list. */ - pthread_mutex_lock(&ua_sess->lock); + lttng::pthread::lock_guard ust_app_session_lock(ua_sess->lock); if (ua_sess->deleted) { - pthread_mutex_unlock(&ua_sess->lock); continue; } @@ -4419,22 +4403,17 @@ void ust_app_unregister(int sock) locked_registry.reset(); } } - cds_list_add(&ua_sess->teardown_node, <a->teardown_head); - pthread_mutex_unlock(&ua_sess->lock); + cds_list_add(&ua_sess->teardown_node, &app.teardown_head); } - /* Remove application from PID hash table */ - ret = lttng_ht_del(ust_app_ht_by_sock, &ust_app_sock_iter); - LTTNG_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 = <a->notify_sock_n.node; + iter.iter.node = &app.notify_sock_n.node; (void) lttng_ht_del(ust_app_ht_by_notify_sock, &iter); /* @@ -4442,16 +4421,47 @@ void ust_app_unregister(int sock) * add replace during app registration because the PID can be reassigned by * the OS. */ - iter.iter.node = <a->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); + iter.iter.node = &app.pid_n.node; + if (lttng_ht_del(ust_app_ht, &iter)) { + DBG3("Unregister app by PID %d failed. This can happen on pid reuse", app.pid); } +} - /* Free memory */ - call_rcu(<a->pid_n.head, delete_ust_app_rcu); +/* + * 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_fd) +{ + struct ust_app *app; + struct lttng_ht_node_ulong *node; + struct lttng_ht_iter ust_app_sock_iter; + int ret; - return; + lttng::urcu::read_lock_guard read_lock; + + /* Get the node reference for a call_rcu */ + lttng_ht_lookup(ust_app_ht_by_sock, (void *) ((unsigned long) sock_fd), &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_FMT("Application unregistering after socket activity: pid={}, socket_fd={}", + app->pid, + sock_fd); + + /* 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); } /* @@ -4790,21 +4800,10 @@ void ust_app_clean_list() * are unregistered prior to this clean-up. */ LTTNG_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) { - lttng::urcu::read_lock_guard read_lock; - - cds_lfht_for_each_entry (ust_app_ht->ht, &iter.iter, app, pid_n.node) { - ret = lttng_ht_del(ust_app_ht, &iter); - LTTNG_ASSERT(!ret); - call_rcu(&app->pid_n.head, delete_ust_app_rcu); - } - } - /* Cleanup socket hash table */ if (ust_app_ht_by_sock) { lttng::urcu::read_lock_guard read_lock; @@ -4812,6 +4811,7 @@ void ust_app_clean_list() 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); LTTNG_ASSERT(!ret); + ust_app_put(app); } } @@ -5492,37 +5492,37 @@ error_rcu_unlock: return -1; } -static int ust_app_flush_app_session(struct ust_app *app, struct ust_app_session *ua_sess) +static int ust_app_flush_app_session(ust_app& app, ust_app_session& ua_sess) { int ret, retval = 0; struct lttng_ht_iter iter; struct ust_app_channel *ua_chan; struct consumer_socket *socket; - DBG("Flushing app session buffers for ust app pid %d", app->pid); + DBG("Flushing app session buffers for ust app pid %d", app.pid); - if (!app->compatible) { + if (!app.compatible) { goto end_not_compatible; } - pthread_mutex_lock(&ua_sess->lock); + pthread_mutex_lock(&ua_sess.lock); - if (ua_sess->deleted) { + if (ua_sess.deleted) { goto end_deleted; } health_code_update(); /* Flushing buffers */ - socket = consumer_find_socket_by_bitness(app->abi.bits_per_long, ua_sess->consumer); + socket = consumer_find_socket_by_bitness(app.abi.bits_per_long, ua_sess.consumer); /* Flush buffers and push metadata. */ - switch (ua_sess->buffer_type) { + switch (ua_sess.buffer_type) { case LTTNG_BUFFER_PER_PID: { lttng::urcu::read_lock_guard read_lock; - cds_lfht_for_each_entry (ua_sess->channels->ht, &iter.iter, ua_chan, node.node) { + cds_lfht_for_each_entry (ua_sess.channels->ht, &iter.iter, ua_chan, node.node) { health_code_update(); ret = consumer_flush_channel(socket, ua_chan->key); if (ret) { @@ -5543,7 +5543,7 @@ static int ust_app_flush_app_session(struct ust_app *app, struct ust_app_session health_code_update(); end_deleted: - pthread_mutex_unlock(&ua_sess->lock); + pthread_mutex_unlock(&ua_sess.lock); end_not_compatible: health_code_update(); @@ -5614,7 +5614,7 @@ static int ust_app_flush_session(struct ltt_ust_session *usess) continue; } - (void) ust_app_flush_app_session(app, ua_sess); + (void) ust_app_flush_app_session(*app, *ua_sess); } break; @@ -7140,13 +7140,9 @@ close_socket: /* * Destroy a ust app data structure and free its memory. */ -void ust_app_destroy(struct ust_app *app) +static void ust_app_destroy(ust_app& app) { - if (!app) { - return; - } - - call_rcu(&app->pid_n.head, delete_ust_app_rcu); + call_rcu(&app.pid_n.head, delete_ust_app_rcu); } /* @@ -7572,7 +7568,6 @@ enum lttng_error_code ust_app_rotate_session(struct ltt_session *session) int ret; enum lttng_error_code cmd_ret = LTTNG_OK; struct lttng_ht_iter iter; - struct ust_app *app; struct ltt_ust_session *usess = session->ust_session; LTTNG_ASSERT(usess); @@ -7640,15 +7635,27 @@ enum lttng_error_code ust_app_rotate_session(struct ltt_session *session) case LTTNG_BUFFER_PER_PID: { lttng::urcu::read_lock_guard read_lock; + ust_app *raw_app; - cds_lfht_for_each_entry (ust_app_ht->ht, &iter.iter, app, pid_n.node) { + cds_lfht_for_each_entry (ust_app_ht->ht, &iter.iter, raw_app, pid_n.node) { struct consumer_socket *socket; struct lttng_ht_iter chan_iter; struct ust_app_channel *ua_chan; struct ust_app_session *ua_sess; lsu::registry_session *registry; + bool app_reference_taken; - ua_sess = lookup_session_by_app(usess, app); + app_reference_taken = ust_app_get(*raw_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; + } + + ust_app_reference app(raw_app); + raw_app = nullptr; + + ua_sess = lookup_session_by_app(usess, app.get()); if (!ua_sess) { /* Session not associated with this app. */ continue; @@ -7663,10 +7670,7 @@ enum lttng_error_code ust_app_rotate_session(struct ltt_session *session) } registry = get_session_registry(ua_sess); - if (!registry) { - DBG("Application session is being torn down. Skip application."); - continue; - } + LTTNG_ASSERT(registry); /* Rotate the data channels. */ cds_lfht_for_each_entry ( @@ -7676,9 +7680,6 @@ enum lttng_error_code ust_app_rotate_session(struct ltt_session *session) 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; } @@ -7690,18 +7691,17 @@ enum lttng_error_code ust_app_rotate_session(struct ltt_session *session) (void) push_metadata(locked_registry, usess->consumer); } + ret = consumer_rotate_channel(socket, registry->_metadata_key, 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; } } + break; } default: @@ -8113,3 +8113,25 @@ lsu::ctl_field_quirks ust_app::ctl_field_quirks() const return v_major <= 9 ? lsu::ctl_field_quirks::UNDERSCORE_PREFIXED_VARIANT_TAG_MAPPINGS : lsu::ctl_field_quirks::NONE; } + +static void ust_app_release(urcu_ref *ref) +{ + auto& app = *lttng::utils::container_of(ref, &ust_app::ref); + + ust_app_unregister(app); + ust_app_destroy(app); +} + +bool ust_app_get(ust_app& 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); +} diff --git a/src/bin/lttng-sessiond/ust-app.hpp b/src/bin/lttng-sessiond/ust-app.hpp index 67af3ec61..64df1c295 100644 --- a/src/bin/lttng-sessiond/ust-app.hpp +++ b/src/bin/lttng-sessiond/ust-app.hpp @@ -250,6 +250,13 @@ struct ust_app_session { * 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. + */ + urcu_ref ref; + /* Traffic initiated from the session daemon to the application. */ int sock; pthread_mutex_t sock_lock; /* Protects sock protocol. */ @@ -362,7 +369,7 @@ struct formatter : formatter { 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); @@ -399,7 +406,6 @@ void ust_app_notify_sock_unregister(int sock); ssize_t ust_app_push_metadata(const lttng::sessiond::ust::registry_session::locked_ptr& 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, uint64_t nb_packets_per_stream); @@ -436,6 +442,12 @@ static inline int ust_app_supported() bool ust_app_supports_notifiers(const struct ust_app *app); bool ust_app_supports_counters(const struct ust_app *app); +bool ust_app_get(ust_app& app); +void ust_app_put(ust_app *app); + +using ust_app_reference = + std::unique_ptr::deleter>; + #else /* HAVE_LIBLTTNG_UST_CTL */ static inline int ust_app_destroy_trace_all(struct ltt_ust_session *usess __attribute__((unused))) @@ -486,7 +498,7 @@ static inline int ust_app_version(struct ust_app *app __attribute__((unused))) return -ENOSYS; } -static inline void ust_app_unregister(int sock __attribute__((unused))) +static inline void ust_app_unregister_by_socket(int sock __attribute__((unused))) { } @@ -609,11 +621,6 @@ static inline ssize_t ust_app_push_metadata(lttng::sessiond::ust::registry_sessi return 0; } -static inline void ust_app_destroy(struct ust_app *app __attribute__((unused))) -{ - return; -} - static inline enum lttng_error_code ust_app_snapshot_record(struct ltt_ust_session *usess __attribute__((unused)), const struct consumer_output *output __attribute__((unused)), @@ -729,6 +736,14 @@ static inline enum lttng_error_code ust_app_open_packets(struct ltt_session *ses return LTTNG_ERR_UNK; } +static inline void ust_app_get(ust_app& app __attribute__((unused))) +{ +} + +static inline void ust_app_put(ust_app *app __attribute__((unused))) +{ +} + #endif /* HAVE_LIBLTTNG_UST_CTL */ #endif /* _LTT_UST_APP_H */ -- 2.34.1