From c1f06ac28fef5498952994e0399312b1fc567f22 Mon Sep 17 00:00:00 2001 From: Florian Dold Date: Fri, 10 May 2019 20:08:01 +0200 Subject: Implement asynchronous scope identifiers. Without entering an asynchronous scope, logs are the same before. When entering an asynchronous scope (either thread-based of scheduler/task-based), all log lines within an asynchronous scope contain its ID. Currently this is only used in GNU Taler, for debugging requests across multiple services. This allows us to get all log lines pertaining to a particular request for a user or another service. --- src/curl/curl.c | 89 ++++++++++++++++++++++++++++++++------ src/include/gnunet_common.h | 64 +++++++++++++++++++++++++++ src/include/gnunet_curl_lib.h | 10 +++++ src/include/gnunet_scheduler_lib.h | 20 +++++++++ src/util/common_logging.c | 83 +++++++++++++++++++++++++++++++++++ src/util/scheduler.c | 43 +++++++++++++++++- 6 files changed, 295 insertions(+), 14 deletions(-) diff --git a/src/curl/curl.c b/src/curl/curl.c index e13c1478f..871401c60 100644 --- a/src/curl/curl.c +++ b/src/curl/curl.c @@ -105,6 +105,18 @@ struct GNUNET_CURL_Job * Buffer for response received from CURL. */ struct GNUNET_CURL_DownloadBuffer db; + + /** + * Headers used for this job, the list needs to be freed + * after the job has finished. + */ + struct curl_slist *job_headers; + + /** + * Header for the async scope id or NULL. + */ + char *aid_header; + }; @@ -134,10 +146,15 @@ struct GNUNET_CURL_Context struct GNUNET_CURL_Job *jobs_tail; /** - * HTTP header "application/json", created once and used - * for all requests that need it. + * Headers common for all requests in the context. + */ + struct curl_slist *common_headers; + + /** + * If non-NULL, the async scope ID is sent in a request + * header of this name. */ - struct curl_slist *json_header; + const char *async_scope_id_header; /** * Function we need to call whenever the event loop's @@ -149,6 +166,7 @@ struct GNUNET_CURL_Context * Closure for @e cb. */ void *cb_cls; + }; @@ -189,13 +207,23 @@ GNUNET_CURL_init (GNUNET_CURL_RescheduleCallback cb, void *cb_cls) ctx->cb_cls = cb_cls; ctx->multi = multi; ctx->share = share; - GNUNET_assert ( - NULL != (ctx->json_header = - curl_slist_append (NULL, "Content-Type: application/json"))); return ctx; } +/** + * Enable sending the async scope ID as a header. + * + * @param ctx the context to enable this for + * @param header_name name of the header to send. + */ +void +GNUNET_CURL_enable_async_scope_header (struct GNUNET_CURL_Context *ctx, const char *header_name) +{ + ctx->async_scope_id_header = header_name; +} + + /** * Callback used when downloading the reply to an HTTP request. * Just appends all of the data to the `buf` in the @@ -259,16 +287,49 @@ GNUNET_CURL_job_add (struct GNUNET_CURL_Context *ctx, void *jcc_cls) { struct GNUNET_CURL_Job *job; + struct curl_slist *all_headers = NULL; + char *aid_header = NULL; if (GNUNET_YES == add_json) - if (CURLE_OK != curl_easy_setopt (eh, CURLOPT_HTTPHEADER, ctx->json_header)) + { + GNUNET_assert ( + NULL != (all_headers = + curl_slist_append (NULL, "Content-Type: application/json"))); + } + + for (struct curl_slist *curr = ctx->common_headers; + curr != NULL; + curr = curr->next) + { + GNUNET_assert ( + NULL != (all_headers = + curl_slist_append (all_headers, "Content-Type: application/json"))); + } + + if (NULL != ctx->async_scope_id_header) + { + struct GNUNET_AsyncScopeSave scope; + + GNUNET_async_scope_get (&scope); + if (GNUNET_YES == scope.have_scope) { - GNUNET_break (0); - curl_easy_cleanup (eh); - return NULL; + aid_header = GNUNET_STRINGS_data_to_string_alloc (&scope.scope_id, + sizeof (struct GNUNET_AsyncScopeId)); + GNUNET_assert (NULL != curl_slist_append(all_headers, aid_header)); } + } + + if (CURLE_OK != curl_easy_setopt (eh, CURLOPT_HTTPHEADER, all_headers)) + { + GNUNET_break (0); + curl_easy_cleanup (eh); + return NULL; + } job = GNUNET_new (struct GNUNET_CURL_Job); + job->job_headers = all_headers; + job->aid_header = aid_header; + if ((CURLE_OK != curl_easy_setopt (eh, CURLOPT_PRIVATE, job)) || (CURLE_OK != curl_easy_setopt (eh, CURLOPT_WRITEFUNCTION, &download_cb)) || @@ -308,6 +369,8 @@ GNUNET_CURL_job_cancel (struct GNUNET_CURL_Job *job) curl_multi_remove_handle (ctx->multi, job->easy_handle)); curl_easy_cleanup (job->easy_handle); GNUNET_free_non_null (job->db.buf); + GNUNET_free_non_null (job->aid_header); + curl_slist_free_all (job->job_headers); GNUNET_free (job); } @@ -401,8 +464,8 @@ download_get_result (struct GNUNET_CURL_DownloadBuffer *db, int GNUNET_CURL_append_header (struct GNUNET_CURL_Context *ctx, const char *header) { - ctx->json_header = curl_slist_append (ctx->json_header, header); - if (NULL == ctx->json_header) + ctx->common_headers = curl_slist_append (ctx->common_headers, header); + if (NULL == ctx->common_headers) return GNUNET_SYSERR; return GNUNET_OK; @@ -599,7 +662,7 @@ GNUNET_CURL_fini (struct GNUNET_CURL_Context *ctx) GNUNET_assert (NULL == ctx->jobs_head); curl_share_cleanup (ctx->share); curl_multi_cleanup (ctx->multi); - curl_slist_free_all (ctx->json_header); + curl_slist_free_all (ctx->common_headers); GNUNET_free (ctx); } diff --git a/src/include/gnunet_common.h b/src/include/gnunet_common.h index 2c40aef79..1f5600381 100644 --- a/src/include/gnunet_common.h +++ b/src/include/gnunet_common.h @@ -319,8 +319,34 @@ struct GNUNET_OperationResultMessage /* Followed by data. */ }; + +/** + * Identifier for an asynchronous execution context. + */ +struct GNUNET_AsyncScopeId +{ + uint32_t bits[16 / sizeof (uint32_t)]; /* = 16 bytes */ +}; + GNUNET_NETWORK_STRUCT_END + +/** + * Saved async scope identifier or root scope. + */ +struct GNUNET_AsyncScopeSave { + /** + * Saved scope. Unused if 'have_scope==GNUNET_NO'. + */ + struct GNUNET_AsyncScopeId scope_id; + + /** + * GNUNET_YES unless this saved scope is the unnamed root scope. + */ + int have_scope; +}; + + /** * Function called with a filename. * @@ -1331,6 +1357,44 @@ struct GNUNET_MessageHeader * GNUNET_copy_message (const struct GNUNET_MessageHeader *msg); +/** + * Set the async scope for the current thread. + * + * @param aid the async scope identifier + * @param old_scope[out] location to save the old scope + */ +void +GNUNET_async_scope_enter (const struct GNUNET_AsyncScopeId *aid, + struct GNUNET_AsyncScopeSave *old_scope); + + +/** + * Clear the current thread's async scope. + * + * @param old_scope scope to restore + */ +void +GNUNET_async_scope_restore (struct GNUNET_AsyncScopeSave *old_scope); + + +/** + * Get the current async scope. + * + * @param[out] scope_ret pointer to where the result is stored + */ +void +GNUNET_async_scope_get (struct GNUNET_AsyncScopeSave *scope_ret); + + +/** + * Generate a fresh async scope identifier. + * + * @param[out] aid_ret pointer to where the result is stored + */ +void +GNUNET_async_scope_fresh (struct GNUNET_AsyncScopeId *aid_ret); + + #if __STDC_VERSION__ < 199901L #if __GNUC__ >= 2 #define __func__ __FUNCTION__ diff --git a/src/include/gnunet_curl_lib.h b/src/include/gnunet_curl_lib.h index 86cb54f6b..84c8d59f8 100644 --- a/src/include/gnunet_curl_lib.h +++ b/src/include/gnunet_curl_lib.h @@ -294,6 +294,16 @@ void GNUNET_CURL_gnunet_scheduler_reschedule (void *cls); +/** + * Enable sending the async scope ID as a header. + * + * @param ctx the context to enable this for + * @param header_name name of the header to send. + */ +void +GNUNET_CURL_enable_async_scope_header (struct GNUNET_CURL_Context *ctx, const char *header_name); + + #endif /** @} */ /* end of group */ diff --git a/src/include/gnunet_scheduler_lib.h b/src/include/gnunet_scheduler_lib.h index 3f4e3c9a8..3f0350f54 100644 --- a/src/include/gnunet_scheduler_lib.h +++ b/src/include/gnunet_scheduler_lib.h @@ -214,6 +214,8 @@ struct GNUNET_SCHEDULER_TaskContext }; + + /** * Function used by event-loop implementations to signal the scheduler * that a particular @a task is ready due to an event specified in the @@ -904,6 +906,24 @@ GNUNET_SCHEDULER_set_select (GNUNET_SCHEDULER_select new_select, void *new_select_cls); + +/** + * Change the async scope for the currently executing task and (transitively) + * for all tasks scheduled by the current task after calling this function. + * Nested tasks can begin their own nested async scope. + * + * Once the current task is finished, the async scope ID is reset to + * its previous value. + * + * Must only be called from a running task. + * + * @param aid the asynchronous scope id to enter + */ +void +GNUNET_SCHEDULER_begin_async_scope (struct GNUNET_AsyncScopeId *aid); + + + #if 0 /* keep Emacsens' auto-indent happy */ { #endif diff --git a/src/util/common_logging.c b/src/util/common_logging.c index 77a595878..5052134f8 100644 --- a/src/util/common_logging.c +++ b/src/util/common_logging.c @@ -95,6 +95,13 @@ struct CustomLogger void *logger_cls; }; + +/** + * Asynchronous scope of the current thread, or NULL if we have not + * entered an async scope yet. + */ +static __thread struct GNUNET_AsyncScopeSave current_async_scope; + /** * The last "bulk" error message that we have been logging. * Note that this message maybe truncated to the first BULK_TRACK_SIZE @@ -838,6 +845,28 @@ output_message (enum GNUNET_ErrorType kind, "* %s", msg); } + else if (GNUNET_YES == current_async_scope.have_scope) + { + static GNUNET_THREAD_LOCAL char id_buf[27]; + char *end; + + /* We're logging, so skip_log must be currently 0. */ + skip_log = 100; + end = GNUNET_STRINGS_data_to_string (¤t_async_scope.scope_id, + sizeof (struct GNUNET_AsyncScopeId), + id_buf, + sizeof (id_buf) - 1); + GNUNET_assert (NULL != end); + *end = '\0'; + skip_log = 0; + FPRINTF (GNUNET_stderr, + "%s %s(%s) %s %s", + datestr, + comp, + id_buf, + GNUNET_error_type_to_string (kind), + msg); + } else { FPRINTF (GNUNET_stderr, @@ -1547,6 +1576,60 @@ GNUNET_log_config_invalid (enum GNUNET_ErrorType kind, } +/** + * Set the async scope for the current thread. + * + * @param aid the async scope identifier + * @param old_scope[out] location to save the old scope + */ +void +GNUNET_async_scope_enter (const struct GNUNET_AsyncScopeId *aid, + struct GNUNET_AsyncScopeSave *old_scope) +{ + *old_scope = current_async_scope; + current_async_scope.have_scope = GNUNET_YES; + current_async_scope.scope_id = *aid; +} + + +/** + * Clear the current thread's async scope. + * + * @param old_scope scope to restore + */ +void +GNUNET_async_scope_restore (struct GNUNET_AsyncScopeSave *old_scope) +{ + current_async_scope = *old_scope; +} + + +/** + * Generate a fresh async scope identifier. + * + * @param[out] aid_ret pointer to where the result is stored + */ +void +GNUNET_async_scope_fresh (struct GNUNET_AsyncScopeId *aid_ret) +{ + GNUNET_CRYPTO_random_block (GNUNET_CRYPTO_QUALITY_WEAK, + aid_ret, + sizeof (struct GNUNET_AsyncScopeId)); +} + + +/** + * Get the current async scope. + * + * @param[out] scope_ret pointer to where the result is stored + */ +void +GNUNET_async_scope_get (struct GNUNET_AsyncScopeSave *scope_ret) +{ + *scope_ret = current_async_scope; +} + + /** * Initializer */ diff --git a/src/util/scheduler.c b/src/util/scheduler.c index 2ddbb8c60..c818e91ee 100644 --- a/src/util/scheduler.c +++ b/src/util/scheduler.c @@ -241,6 +241,11 @@ struct GNUNET_SCHEDULER_Task int num_backtrace_strings; #endif + /** + * Asynchronous scope of the task that scheduled this scope, + */ + struct GNUNET_AsyncScopeSave scope; + }; @@ -1105,6 +1110,7 @@ GNUNET_SCHEDULER_add_at_with_priority (struct GNUNET_TIME_Absolute at, GNUNET_assert (NULL != scheduler_driver); GNUNET_assert (NULL != task); t = GNUNET_new (struct GNUNET_SCHEDULER_Task); + GNUNET_async_scope_get (&t->scope); t->callback = task; t->callback_cls = task_cls; t->read_fd = -1; @@ -1293,6 +1299,7 @@ GNUNET_SCHEDULER_add_shutdown (GNUNET_SCHEDULER_TaskCallback task, GNUNET_assert (NULL != scheduler_driver); GNUNET_assert (NULL != task); t = GNUNET_new (struct GNUNET_SCHEDULER_Task); + GNUNET_async_scope_get (&t->scope); t->callback = task; t->callback_cls = task_cls; t->read_fd = -1; @@ -1411,6 +1418,7 @@ add_without_sets (struct GNUNET_TIME_Relative delay, GNUNET_assert (NULL != scheduler_driver); GNUNET_assert (NULL != task); t = GNUNET_new (struct GNUNET_SCHEDULER_Task); + GNUNET_async_scope_get (&t->scope); init_fd_info (t, &read_nh, read_nh ? 1 : 0, @@ -1882,6 +1890,7 @@ GNUNET_SCHEDULER_add_select (enum GNUNET_SCHEDULER_Priority prio, task, task_cls); t = GNUNET_new (struct GNUNET_SCHEDULER_Task); + GNUNET_async_scope_get (&t->scope); init_fd_info (t, read_nhandles, read_nhandles_len, @@ -2114,7 +2123,15 @@ GNUNET_SCHEDULER_do_work (struct GNUNET_SCHEDULER_Handle *sh) "Running task %p\n", pos); GNUNET_assert (NULL != pos->callback); - pos->callback (pos->callback_cls); + { + struct GNUNET_AsyncScopeSave old_scope; + if (pos->scope.have_scope) + GNUNET_async_scope_enter (&pos->scope.scope_id, &old_scope); + else + GNUNET_async_scope_get (&old_scope); + pos->callback (pos->callback_cls); + GNUNET_async_scope_restore (&old_scope); + } if (NULL != pos->fds) { int del_result = scheduler_driver->del (scheduler_driver->cls, pos); @@ -2513,4 +2530,28 @@ GNUNET_SCHEDULER_driver_select () } +/** + * Change the async scope for the currently executing task and (transitively) + * for all tasks scheduled by the current task after calling this function. + * Nested tasks can begin their own nested async scope. + * + * Once the current task is finished, the async scope ID is reset to + * its previous value. + * + * Must only be called from a running task. + * + * @param aid the asynchronous scope id to enter + */ +void +GNUNET_SCHEDULER_begin_async_scope (struct GNUNET_AsyncScopeId *aid) +{ + struct GNUNET_AsyncScopeSave dummy_old_scope; + + GNUNET_assert (NULL != active_task); + /* Since we're in a task, the context will be automatically + restored by the scheduler. */ + GNUNET_async_scope_enter (aid, &dummy_old_scope); +} + + /* end of scheduler.c */ -- cgit v1.2.3