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.

2 files changed, 125 insertions, 1 deletions

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 (&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,
@@ -1548,6 +1577,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
  */
 void __attribute__ ((constructor))
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 */