Implement asynchronous scope identifiers.
authorFlorian Dold <florian.dold@gmail.com>
Fri, 10 May 2019 18:08:01 +0000 (20:08 +0200)
committerFlorian Dold <florian.dold@gmail.com>
Fri, 10 May 2019 18:10:02 +0000 (20:10 +0200)
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
src/include/gnunet_common.h
src/include/gnunet_curl_lib.h
src/include/gnunet_scheduler_lib.h
src/util/common_logging.c
src/util/scheduler.c

index e13c1478ff1b223d9ac48a3872c742fb5a3e1be4..871401c60cafef78b220885bd49c91c3b50c5dc2 100644 (file)
@@ -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);
 }
 
index 2c40aef797e348700a4b92699726843707ffe043..1f56003812c90e9f9061916f02108268b0acbe49 100644 (file)
@@ -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__
index 86cb54f6b8ff31cfc9bc4dec240240bc23028354..84c8d59f8ee9286c2c8a922b3667a1bd0101c3de 100644 (file)
@@ -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 */
 
index 3f4e3c9a80b35182854d6408b414598b960e51bc..3f0350f54d8aa52c0fb39be07dbfe71c0e2eca39 100644 (file)
@@ -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
index 77a59587814c63bd75c99d6fbf4fca322a6eabb6..5052134f84d71ca6809dceee212fa0b4335218d3 100644 (file)
@@ -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 (&current_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
  */
index 2ddbb8c60f06daf7b4f8f6f72b25cb4fa30147c9..c818e91ee639c7c4f159da140e8f774c78004b43 100644 (file)
@@ -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 */