diff --git a/trusty/storage/proxy/Android.bp b/trusty/storage/proxy/Android.bp index e952ee0bc..2e97ee0fe 100644 --- a/trusty/storage/proxy/Android.bp +++ b/trusty/storage/proxy/Android.bp @@ -28,6 +28,7 @@ cc_binary { "rpmb.c", "storage.c", "proxy.c", + "watchdog.cpp", ], shared_libs: [ diff --git a/trusty/storage/proxy/proxy.c b/trusty/storage/proxy/proxy.c index 4f77fa2ea..c89c5b6fd 100644 --- a/trusty/storage/proxy/proxy.c +++ b/trusty/storage/proxy/proxy.c @@ -31,6 +31,7 @@ #include "log.h" #include "rpmb.h" #include "storage.h" +#include "watchdog.h" #define REQ_BUFFER_SIZE 4096 static uint8_t req_buffer[REQ_BUFFER_SIZE + 1]; @@ -73,6 +74,8 @@ static void show_usage_and_exit(int code) { static int handle_req(struct storage_msg* msg, const void* req, size_t req_len) { int rc; + struct watcher* watcher = watch_start("request", msg); + if ((msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) && msg->cmd != STORAGE_RPMB_SEND && msg->cmd != STORAGE_FILE_WRITE) { /* @@ -81,14 +84,14 @@ static int handle_req(struct storage_msg* msg, const void* req, size_t req_len) */ ALOGE("cmd 0x%x: post commit option is not implemented\n", msg->cmd); msg->result = STORAGE_ERR_UNIMPLEMENTED; - return ipc_respond(msg, NULL, 0); + goto err_response; } if (msg->flags & STORAGE_MSG_FLAG_PRE_COMMIT) { - rc = storage_sync_checkpoint(); + rc = storage_sync_checkpoint(watcher); if (rc < 0) { msg->result = STORAGE_ERR_SYNC_FAILURE; - return ipc_respond(msg, NULL, 0); + goto err_response; } } @@ -99,61 +102,65 @@ static int handle_req(struct storage_msg* msg, const void* req, size_t req_len) if (rc != 0) { ALOGE("is_data_checkpoint_active failed in an unexpected way. Aborting.\n"); msg->result = STORAGE_ERR_GENERIC; - return ipc_respond(msg, NULL, 0); + goto err_response; } else if (is_checkpoint_active) { ALOGE("Checkpoint in progress, dropping write ...\n"); msg->result = STORAGE_ERR_GENERIC; - return ipc_respond(msg, NULL, 0); + goto err_response; } } switch (msg->cmd) { case STORAGE_FILE_DELETE: - rc = storage_file_delete(msg, req, req_len); + rc = storage_file_delete(msg, req, req_len, watcher); break; case STORAGE_FILE_OPEN: - rc = storage_file_open(msg, req, req_len); + rc = storage_file_open(msg, req, req_len, watcher); break; case STORAGE_FILE_CLOSE: - rc = storage_file_close(msg, req, req_len); + rc = storage_file_close(msg, req, req_len, watcher); break; case STORAGE_FILE_WRITE: - rc = storage_file_write(msg, req, req_len); + rc = storage_file_write(msg, req, req_len, watcher); break; case STORAGE_FILE_READ: - rc = storage_file_read(msg, req, req_len); + rc = storage_file_read(msg, req, req_len, watcher); break; case STORAGE_FILE_GET_SIZE: - rc = storage_file_get_size(msg, req, req_len); + rc = storage_file_get_size(msg, req, req_len, watcher); break; case STORAGE_FILE_SET_SIZE: - rc = storage_file_set_size(msg, req, req_len); + rc = storage_file_set_size(msg, req, req_len, watcher); break; case STORAGE_FILE_GET_MAX_SIZE: - rc = storage_file_get_max_size(msg, req, req_len); + rc = storage_file_get_max_size(msg, req, req_len, watcher); break; case STORAGE_RPMB_SEND: - rc = rpmb_send(msg, req, req_len); + rc = rpmb_send(msg, req, req_len, watcher); break; default: ALOGE("unhandled command 0x%x\n", msg->cmd); msg->result = STORAGE_ERR_UNIMPLEMENTED; - rc = 1; + goto err_response; } - if (rc > 0) { - /* still need to send response */ - rc = ipc_respond(msg, NULL, 0); - } + /* response was sent in handler */ + goto finish; + +err_response: + rc = ipc_respond(msg, NULL, 0); + +finish: + watch_finish(watcher); return rc; } diff --git a/trusty/storage/proxy/rpmb.c b/trusty/storage/proxy/rpmb.c index b1b823269..22a85a72b 100644 --- a/trusty/storage/proxy/rpmb.c +++ b/trusty/storage/proxy/rpmb.c @@ -321,7 +321,8 @@ static enum scsi_result check_sg_io_hdr(const sg_io_hdr_t* io_hdrp) { return SCSI_RES_ERR; } -static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req) { +static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req, + struct watcher* watcher) { union { struct mmc_ioc_multi_cmd multi; uint8_t raw[sizeof(struct mmc_ioc_multi_cmd) + sizeof(struct mmc_ioc_cmd) * 3]; @@ -375,14 +376,17 @@ static int send_mmc_rpmb_req(int mmc_fd, const struct storage_rpmb_send_req* req cmd++; } + watch_progress(watcher, "rpmb mmc ioctl"); rc = ioctl(mmc_fd, MMC_IOC_MULTI_CMD, &mmc.multi); + watch_progress(watcher, "rpmb mmc ioctl done"); if (rc < 0) { ALOGE("%s: mmc ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); } return rc; } -static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) { +static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req, + struct watcher* watcher) { int rc; int wl_rc; const uint8_t* write_buf = req->payload; @@ -410,7 +414,9 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) set_sg_io_hdr(&io_hdr, SG_DXFER_TO_DEV, sizeof(out_cdb), sizeof(sense_buffer), req->reliable_write_size, (void*)write_buf, (unsigned char*)&out_cdb, sense_buffer); + watch_progress(watcher, "rpmb ufs reliable write"); rc = ioctl(sg_fd, SG_IO, &io_hdr); + watch_progress(watcher, "rpmb ufs reliable write done"); if (rc < 0) { ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); goto err_op; @@ -435,7 +441,9 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) set_sg_io_hdr(&io_hdr, SG_DXFER_TO_DEV, sizeof(out_cdb), sizeof(sense_buffer), req->write_size, (void*)write_buf, (unsigned char*)&out_cdb, sense_buffer); + watch_progress(watcher, "rpmb ufs write"); rc = ioctl(sg_fd, SG_IO, &io_hdr); + watch_progress(watcher, "rpmb ufs write done"); if (rc < 0) { ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); goto err_op; @@ -450,7 +458,9 @@ static int send_ufs_rpmb_req(int sg_fd, const struct storage_rpmb_send_req* req) sg_io_hdr_t io_hdr; set_sg_io_hdr(&io_hdr, SG_DXFER_FROM_DEV, sizeof(in_cdb), sizeof(sense_buffer), req->read_size, read_buf, (unsigned char*)&in_cdb, sense_buffer); + watch_progress(watcher, "rpmb ufs read"); rc = ioctl(sg_fd, SG_IO, &io_hdr); + watch_progress(watcher, "rpmb ufs read done"); if (rc < 0) { ALOGE("%s: ufs ioctl failed: %d, %s\n", __func__, rc, strerror(errno)); } @@ -487,7 +497,7 @@ static int send_virt_rpmb_req(int rpmb_fd, void* read_buf, size_t read_size, con return rc; } -int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) { +int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len, struct watcher* watcher) { int rc; const struct storage_rpmb_send_req* req = r; @@ -523,13 +533,13 @@ int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len) { } if (dev_type == MMC_RPMB) { - rc = send_mmc_rpmb_req(rpmb_fd, req); + rc = send_mmc_rpmb_req(rpmb_fd, req, watcher); if (rc < 0) { msg->result = STORAGE_ERR_GENERIC; goto err_response; } } else if (dev_type == UFS_RPMB) { - rc = send_ufs_rpmb_req(rpmb_fd, req); + rc = send_ufs_rpmb_req(rpmb_fd, req, watcher); if (rc < 0) { ALOGE("send_ufs_rpmb_req failed: %d, %s\n", rc, strerror(errno)); msg->result = STORAGE_ERR_GENERIC; diff --git a/trusty/storage/proxy/rpmb.h b/trusty/storage/proxy/rpmb.h index f4e1b511d..04bdf9a6a 100644 --- a/trusty/storage/proxy/rpmb.h +++ b/trusty/storage/proxy/rpmb.h @@ -18,8 +18,10 @@ #include #include +#include "watchdog.h" + enum dev_type { UNKNOWN_RPMB, MMC_RPMB, VIRT_RPMB, UFS_RPMB, SOCK_RPMB }; int rpmb_open(const char* rpmb_devname, enum dev_type dev_type); -int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len); +int rpmb_send(struct storage_msg* msg, const void* r, size_t req_len, struct watcher* watcher); void rpmb_close(void); diff --git a/trusty/storage/proxy/storage.c b/trusty/storage/proxy/storage.c index a96ddcbd9..229948119 100644 --- a/trusty/storage/proxy/storage.c +++ b/trusty/storage/proxy/storage.c @@ -31,6 +31,7 @@ #include "ipc.h" #include "log.h" #include "storage.h" +#include "watchdog.h" #define FD_TBL_SIZE 64 #define MAX_READ_SIZE 4096 @@ -180,9 +181,8 @@ static ssize_t read_with_retry(int fd, void *buf_, size_t size, off_t offset) return rcnt; } -int storage_file_delete(struct storage_msg *msg, - const void *r, size_t req_len) -{ +int storage_file_delete(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { char *path = NULL; const struct storage_file_delete_req *req = r; @@ -208,6 +208,7 @@ int storage_file_delete(struct storage_msg *msg, goto err_response; } + watch_progress(watcher, "unlinking file"); rc = unlink(path); if (rc < 0) { rc = errno; @@ -231,8 +232,9 @@ err_response: return ipc_respond(msg, NULL, 0); } -static void sync_parent(const char* path) { +static void sync_parent(const char* path, struct watcher* watcher) { int parent_fd; + watch_progress(watcher, "syncing parent"); char* parent_path = dirname(path); parent_fd = TEMP_FAILURE_RETRY(open(parent_path, O_RDONLY)); if (parent_fd >= 0) { @@ -242,9 +244,11 @@ static void sync_parent(const char* path) { ALOGE("%s: failed to open parent directory \"%s\" for sync: %s\n", __func__, parent_path, strerror(errno)); } + watch_progress(watcher, "done syncing parent"); } -int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len) { +int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { char* path = NULL; const struct storage_file_open_req *req = r; struct storage_file_open_resp resp = {0}; @@ -306,7 +310,7 @@ int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len) { char* parent_path = dirname(path); rc = mkdir(parent_path, S_IRWXU); if (rc == 0) { - sync_parent(parent_path); + sync_parent(parent_path, watcher); } else if (errno != EEXIST) { ALOGE("%s: Could not create parent directory \"%s\": %s\n", __func__, parent_path, strerror(errno)); @@ -347,7 +351,7 @@ int storage_file_open(struct storage_msg* msg, const void* r, size_t req_len) { } if (open_flags & O_CREAT) { - sync_parent(path); + sync_parent(path, watcher); } free(path); @@ -375,9 +379,8 @@ err_response: return ipc_respond(msg, NULL, 0); } -int storage_file_close(struct storage_msg *msg, - const void *r, size_t req_len) -{ +int storage_file_close(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { const struct storage_file_close_req *req = r; if (req_len != sizeof(*req)) { @@ -390,7 +393,9 @@ int storage_file_close(struct storage_msg *msg, int fd = remove_fd(req->handle); ALOGV("%s: handle = %u: fd = %u\n", __func__, req->handle, fd); + watch_progress(watcher, "fsyncing before file close"); int rc = fsync(fd); + watch_progress(watcher, "done fsyncing before file close"); if (rc < 0) { rc = errno; ALOGE("%s: fsync failed for fd=%u: %s\n", @@ -414,10 +419,8 @@ err_response: return ipc_respond(msg, NULL, 0); } - -int storage_file_write(struct storage_msg *msg, - const void *r, size_t req_len) -{ +int storage_file_write(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { int rc; const struct storage_file_write_req *req = r; @@ -429,17 +432,20 @@ int storage_file_write(struct storage_msg *msg, } int fd = lookup_fd(req->handle, true); + watch_progress(watcher, "writing"); if (write_with_retry(fd, &req->data[0], req_len - sizeof(*req), req->offset) < 0) { + watch_progress(watcher, "writing done w/ error"); rc = errno; ALOGW("%s: error writing file (fd=%d): %s\n", __func__, fd, strerror(errno)); msg->result = translate_errno(rc); goto err_response; } + watch_progress(watcher, "writing done"); if (msg->flags & STORAGE_MSG_FLAG_POST_COMMIT) { - rc = storage_sync_checkpoint(); + rc = storage_sync_checkpoint(watcher); if (rc < 0) { msg->result = STORAGE_ERR_SYNC_FAILURE; goto err_response; @@ -452,10 +458,8 @@ err_response: return ipc_respond(msg, NULL, 0); } - -int storage_file_read(struct storage_msg *msg, - const void *r, size_t req_len) -{ +int storage_file_read(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { int rc; const struct storage_file_read_req *req = r; @@ -474,8 +478,10 @@ int storage_file_read(struct storage_msg *msg, } int fd = lookup_fd(req->handle, false); + watch_progress(watcher, "reading"); ssize_t read_res = read_with_retry(fd, read_rsp.hdr.data, req->size, (off_t)req->offset); + watch_progress(watcher, "reading done"); if (read_res < 0) { rc = errno; ALOGW("%s: error reading file (fd=%d): %s\n", @@ -491,10 +497,8 @@ err_response: return ipc_respond(msg, NULL, 0); } - -int storage_file_get_size(struct storage_msg *msg, - const void *r, size_t req_len) -{ +int storage_file_get_size(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { const struct storage_file_get_size_req *req = r; struct storage_file_get_size_resp resp = {0}; @@ -507,7 +511,9 @@ int storage_file_get_size(struct storage_msg *msg, struct stat stat; int fd = lookup_fd(req->handle, false); + watch_progress(watcher, "fstat"); int rc = fstat(fd, &stat); + watch_progress(watcher, "fstat done"); if (rc < 0) { rc = errno; ALOGE("%s: error stat'ing file (fd=%d): %s\n", @@ -524,10 +530,8 @@ err_response: return ipc_respond(msg, NULL, 0); } - -int storage_file_set_size(struct storage_msg *msg, - const void *r, size_t req_len) -{ +int storage_file_set_size(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { const struct storage_file_set_size_req *req = r; if (req_len != sizeof(*req)) { @@ -538,7 +542,9 @@ int storage_file_set_size(struct storage_msg *msg, } int fd = lookup_fd(req->handle, true); + watch_progress(watcher, "ftruncate"); int rc = TEMP_FAILURE_RETRY(ftruncate(fd, req->size)); + watch_progress(watcher, "ftruncate done"); if (rc < 0) { rc = errno; ALOGE("%s: error truncating file (fd=%d): %s\n", @@ -553,7 +559,8 @@ err_response: return ipc_respond(msg, NULL, 0); } -int storage_file_get_max_size(struct storage_msg* msg, const void* r, size_t req_len) { +int storage_file_get_max_size(struct storage_msg* msg, const void* r, size_t req_len, + struct watcher* watcher) { const struct storage_file_get_max_size_req* req = r; struct storage_file_get_max_size_resp resp = {0}; uint64_t max_size = 0; @@ -566,7 +573,9 @@ int storage_file_get_max_size(struct storage_msg* msg, const void* r, size_t req struct stat stat; int fd = lookup_fd(req->handle, false); + watch_progress(watcher, "fstat to get max size"); int rc = fstat(fd, &stat); + watch_progress(watcher, "fstat to get max size done"); if (rc < 0) { ALOGE("%s: error stat'ing file (fd=%d): %s\n", __func__, fd, strerror(errno)); goto err_response; @@ -606,10 +615,10 @@ int storage_init(const char *dirname) return 0; } -int storage_sync_checkpoint(void) -{ +int storage_sync_checkpoint(struct watcher* watcher) { int rc; + watch_progress(watcher, "sync fd table"); /* sync fd table and reset it to clean state first */ for (uint fd = 0; fd < FD_TBL_SIZE; fd++) { if (fd_state[fd] == SS_DIRTY) { @@ -634,10 +643,12 @@ int storage_sync_checkpoint(void) * because our fd table is large enough to handle the few open files we * use. */ - sync(); - fs_state = SS_CLEAN; + watch_progress(watcher, "all fs sync"); + sync(); + fs_state = SS_CLEAN; } + watch_progress(watcher, "done syncing"); + return 0; } - diff --git a/trusty/storage/proxy/storage.h b/trusty/storage/proxy/storage.h index 77bfa13fb..f29fdf2e8 100644 --- a/trusty/storage/proxy/storage.h +++ b/trusty/storage/proxy/storage.h @@ -18,30 +18,33 @@ #include #include -int storage_file_delete(struct storage_msg *msg, - const void *req, size_t req_len); +/* Defined in watchdog.h */ +struct watcher; -int storage_file_open(struct storage_msg *msg, - const void *req, size_t req_len); +int storage_file_delete(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_file_close(struct storage_msg *msg, - const void *req, size_t req_len); +int storage_file_open(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_file_write(struct storage_msg *msg, - const void *req, size_t req_len); +int storage_file_close(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_file_read(struct storage_msg *msg, - const void *req, size_t req_len); +int storage_file_write(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_file_get_size(struct storage_msg *msg, - const void *req, size_t req_len); +int storage_file_read(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_file_set_size(struct storage_msg *msg, - const void *req, size_t req_len); +int storage_file_get_size(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_file_get_max_size(struct storage_msg* msg, const void* req, size_t req_len); +int storage_file_set_size(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_init(const char *dirname); +int storage_file_get_max_size(struct storage_msg* msg, const void* req, size_t req_len, + struct watcher* watcher); -int storage_sync_checkpoint(void); +int storage_init(const char* dirname); +int storage_sync_checkpoint(struct watcher* watcher); diff --git a/trusty/storage/proxy/watchdog.cpp b/trusty/storage/proxy/watchdog.cpp new file mode 100644 index 000000000..6c09e2639 --- /dev/null +++ b/trusty/storage/proxy/watchdog.cpp @@ -0,0 +1,208 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include "watchdog.h" + +#include +#include +#include +#include +#include + +#include + +struct watcher { + watcher(const char* id, const struct storage_msg* request); + void SetState(const char* new_state); + void LogTimeout(); + void LogFinished(); + + const char* id_; + uint32_t cmd_; + uint32_t op_id_; + uint32_t flags_; + const char* state_; + + using clock = std::chrono::high_resolution_clock; + clock::time_point start_; + clock::time_point state_change_; + std::chrono::milliseconds Elapsed(clock::time_point end); + + bool triggered_; +}; + +watcher::watcher(const char* id, const struct storage_msg* request) + : id_(id), state_(nullptr), triggered_(false) { + cmd_ = request->cmd; + op_id_ = request->op_id; + flags_ = request->flags; + + start_ = clock::now(); + state_change_ = start_; +} + +void watcher::SetState(const char* new_state) { + state_ = new_state; + state_change_ = clock::now(); +} + +void watcher::LogTimeout() { + if (!triggered_) { + triggered_ = true; + LOG(ERROR) << "Storageproxyd watchdog triggered: " << id_ << " cmd: " << cmd_ + << " op_id: " << op_id_ << " flags: " << flags_; + } + if (state_) { + LOG(ERROR) << "...elapsed: " << Elapsed(clock::now()).count() << "ms (" << state_ << " " + << Elapsed(state_change_).count() << "ms)"; + } else { + LOG(ERROR) << "...elapsed: " << Elapsed(clock::now()).count() << "ms"; + } +} + +void watcher::LogFinished() { + if (triggered_) { + LOG(ERROR) << "...completed: " << Elapsed(clock::now()).count() << "ms"; + } +} + +std::chrono::milliseconds watcher::Elapsed(watcher::clock::time_point end) { + return std::chrono::duration_cast(end - start_); +} + +namespace { + +class Watchdog { + private: + static constexpr std::chrono::milliseconds kDefaultTimeoutMs = std::chrono::milliseconds(500); + static constexpr std::chrono::milliseconds kMaxTimeoutMs = std::chrono::seconds(10); + + public: + Watchdog() : watcher_(), done_(false) {} + ~Watchdog(); + struct watcher* RegisterWatch(const char* id, const struct storage_msg* request); + void AddProgress(struct watcher* watcher, const char* state); + void UnRegisterWatch(struct watcher* watcher); + + private: + // Syncronizes access to watcher_ and watcher_change_ between the main + // thread and watchdog loop thread. watcher_ may only be modified by the + // main thread; the watchdog loop is read-only. + std::mutex watcher_mutex_; + std::unique_ptr watcher_; + std::condition_variable watcher_change_; + + std::thread watchdog_thread_; + bool done_; + + void WatchdogLoop(); + void LogWatchdogTriggerLocked(); +}; + +Watchdog gWatchdog; + +} // Anonymous namespace + +// Assumes that caller is single-threaded. If we want to use this from a +// multi-threaded context we need to ensure that the watchdog thread is +// initialized safely once and accessing an existing watcher is done while the +// watcher lock is held. +struct watcher* Watchdog::RegisterWatch(const char* id, const struct storage_msg* request) { + if (!watchdog_thread_.joinable()) { + watchdog_thread_ = std::thread(&Watchdog::WatchdogLoop, this); + } + if (watcher_) { + LOG(ERROR) << "Replacing registered watcher " << watcher_->id_; + UnRegisterWatch(watcher_.get()); + } + + struct watcher* ret = nullptr; + { + std::unique_lock watcherLock(watcher_mutex_); + watcher_ = std::make_unique(id, request); + ret = watcher_.get(); + } + watcher_change_.notify_one(); + return ret; +} + +void Watchdog::UnRegisterWatch(struct watcher* watcher) { + { + std::lock_guard watcherLock(watcher_mutex_); + if (!watcher_) { + LOG(ERROR) << "Cannot unregister watcher, no watcher registered"; + return; + } + if (watcher_.get() != watcher) { + LOG(ERROR) << "Unregistering watcher that doesn't match current watcher"; + } + watcher_->LogFinished(); + watcher_.reset(nullptr); + } + watcher_change_.notify_one(); +} + +void Watchdog::AddProgress(struct watcher* watcher, const char* state) { + std::lock_guard watcherLock(watcher_mutex_); + if (watcher_.get() != watcher) { + LOG(ERROR) << "Watcher was not registered, cannot log progress: " << state; + return; + } + watcher->SetState(state); +} + +void Watchdog::WatchdogLoop() { + std::unique_lock lock(watcher_mutex_); + std::chrono::milliseconds timeout = kDefaultTimeoutMs; + + while (!done_) { + // wait for a watch to be registered + watcher_change_.wait(lock, [this] { return !!watcher_; }); + + // wait for the timeout or unregistration + timeout = kDefaultTimeoutMs; + do { + if (!watcher_change_.wait_for(lock, timeout, [this] { return !watcher_; })) { + watcher_->LogTimeout(); + timeout = std::min(timeout * 2, kMaxTimeoutMs); + } + } while (!!watcher_); + } +} + +Watchdog::~Watchdog() { + { + std::lock_guard watcherLock(watcher_mutex_); + watcher_.reset(nullptr); + done_ = true; + } + watcher_change_.notify_one(); + if (watchdog_thread_.joinable()) { + watchdog_thread_.join(); + } +} + +struct watcher* watch_start(const char* id, const struct storage_msg* request) { + return gWatchdog.RegisterWatch(id, request); +} + +void watch_progress(struct watcher* watcher, const char* state) { + gWatchdog.AddProgress(watcher, state); +} + +void watch_finish(struct watcher* watcher) { + gWatchdog.UnRegisterWatch(watcher); +} diff --git a/trusty/storage/proxy/watchdog.h b/trusty/storage/proxy/watchdog.h new file mode 100644 index 000000000..9162fcb97 --- /dev/null +++ b/trusty/storage/proxy/watchdog.h @@ -0,0 +1,59 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include "storage.h" + +#ifdef __cplusplus +extern "C" { +#endif + +struct watcher; + +/** + * watch_start() - Create a watcher for a storage request + * @id: Identifier string to distinguish watchers + * @request: Incoming request from Trusty storage service + * + * Create a watcher that will start logging if not finished before a timeout. + * Only one watcher may be active at a time, and this function may only be + * called from a single thread. + */ +struct watcher* watch_start(const char* id, const struct storage_msg* request); + +/** + * watch_progress() - Note progress on servicing the current request + * @watcher: Current watcher, created by watch() + * + * Sets the current progress state of the watcher, to allow for more granular + * reporting of what exactly is stuck if the timeout is reached. + */ +void watch_progress(struct watcher* watcher, const char* state); + +/** + * watch_finish() - Finish watching and unregister the watch + * @watcher: Current watcher, created by watch(). Takes ownership of this pointer. + * + * Finish the current watch task. This function takes ownership of the watcher + * and destroys it, so @watcher must not be used again after calling this + * function. + */ +void watch_finish(struct watcher* watcher); + +#ifdef __cplusplus +} +#endif