aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorFlorian Dold <florian.dold@gmail.com>2019-05-10 20:08:01 +0200
committerFlorian Dold <florian.dold@gmail.com>2019-05-10 20:10:02 +0200
commitc1f06ac28fef5498952994e0399312b1fc567f22 (patch)
treead71f80bb08bfe20ff33880509263d78f334409b
parentd1d18e6492708a0ce758ddd8c509f21b0ecbf6a0 (diff)
downloadgnunet-c1f06ac28fef5498952994e0399312b1fc567f22.tar.gz
gnunet-c1f06ac28fef5498952994e0399312b1fc567f22.zip
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.
-rw-r--r--src/curl/curl.c89
-rw-r--r--src/include/gnunet_common.h64
-rw-r--r--src/include/gnunet_curl_lib.h10
-rw-r--r--src/include/gnunet_scheduler_lib.h20
-rw-r--r--src/util/common_logging.c83
-rw-r--r--src/util/scheduler.c43
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
105 * Buffer for response received from CURL. 105 * Buffer for response received from CURL.
106 */ 106 */
107 struct GNUNET_CURL_DownloadBuffer db; 107 struct GNUNET_CURL_DownloadBuffer db;
108
109 /**
110 * Headers used for this job, the list needs to be freed
111 * after the job has finished.
112 */
113 struct curl_slist *job_headers;
114
115 /**
116 * Header for the async scope id or NULL.
117 */
118 char *aid_header;
119
108}; 120};
109 121
110 122
@@ -134,10 +146,15 @@ struct GNUNET_CURL_Context
134 struct GNUNET_CURL_Job *jobs_tail; 146 struct GNUNET_CURL_Job *jobs_tail;
135 147
136 /** 148 /**
137 * HTTP header "application/json", created once and used 149 * Headers common for all requests in the context.
138 * for all requests that need it. 150 */
151 struct curl_slist *common_headers;
152
153 /**
154 * If non-NULL, the async scope ID is sent in a request
155 * header of this name.
139 */ 156 */
140 struct curl_slist *json_header; 157 const char *async_scope_id_header;
141 158
142 /** 159 /**
143 * Function we need to call whenever the event loop's 160 * Function we need to call whenever the event loop's
@@ -149,6 +166,7 @@ struct GNUNET_CURL_Context
149 * Closure for @e cb. 166 * Closure for @e cb.
150 */ 167 */
151 void *cb_cls; 168 void *cb_cls;
169
152}; 170};
153 171
154 172
@@ -189,14 +207,24 @@ GNUNET_CURL_init (GNUNET_CURL_RescheduleCallback cb, void *cb_cls)
189 ctx->cb_cls = cb_cls; 207 ctx->cb_cls = cb_cls;
190 ctx->multi = multi; 208 ctx->multi = multi;
191 ctx->share = share; 209 ctx->share = share;
192 GNUNET_assert (
193 NULL != (ctx->json_header =
194 curl_slist_append (NULL, "Content-Type: application/json")));
195 return ctx; 210 return ctx;
196} 211}
197 212
198 213
199/** 214/**
215 * Enable sending the async scope ID as a header.
216 *
217 * @param ctx the context to enable this for
218 * @param header_name name of the header to send.
219 */
220void
221GNUNET_CURL_enable_async_scope_header (struct GNUNET_CURL_Context *ctx, const char *header_name)
222{
223 ctx->async_scope_id_header = header_name;
224}
225
226
227/**
200 * Callback used when downloading the reply to an HTTP request. 228 * Callback used when downloading the reply to an HTTP request.
201 * Just appends all of the data to the `buf` in the 229 * Just appends all of the data to the `buf` in the
202 * `struct DownloadBuffer` for further processing. The size of 230 * `struct DownloadBuffer` for further processing. The size of
@@ -259,16 +287,49 @@ GNUNET_CURL_job_add (struct GNUNET_CURL_Context *ctx,
259 void *jcc_cls) 287 void *jcc_cls)
260{ 288{
261 struct GNUNET_CURL_Job *job; 289 struct GNUNET_CURL_Job *job;
290 struct curl_slist *all_headers = NULL;
291 char *aid_header = NULL;
262 292
263 if (GNUNET_YES == add_json) 293 if (GNUNET_YES == add_json)
264 if (CURLE_OK != curl_easy_setopt (eh, CURLOPT_HTTPHEADER, ctx->json_header)) 294 {
295 GNUNET_assert (
296 NULL != (all_headers =
297 curl_slist_append (NULL, "Content-Type: application/json")));
298 }
299
300 for (struct curl_slist *curr = ctx->common_headers;
301 curr != NULL;
302 curr = curr->next)
303 {
304 GNUNET_assert (
305 NULL != (all_headers =
306 curl_slist_append (all_headers, "Content-Type: application/json")));
307 }
308
309 if (NULL != ctx->async_scope_id_header)
310 {
311 struct GNUNET_AsyncScopeSave scope;
312
313 GNUNET_async_scope_get (&scope);
314 if (GNUNET_YES == scope.have_scope)
265 { 315 {
266 GNUNET_break (0); 316 aid_header = GNUNET_STRINGS_data_to_string_alloc (&scope.scope_id,
267 curl_easy_cleanup (eh); 317 sizeof (struct GNUNET_AsyncScopeId));
268 return NULL; 318 GNUNET_assert (NULL != curl_slist_append(all_headers, aid_header));
269 } 319 }
320 }
321
322 if (CURLE_OK != curl_easy_setopt (eh, CURLOPT_HTTPHEADER, all_headers))
323 {
324 GNUNET_break (0);
325 curl_easy_cleanup (eh);
326 return NULL;
327 }
270 328
271 job = GNUNET_new (struct GNUNET_CURL_Job); 329 job = GNUNET_new (struct GNUNET_CURL_Job);
330 job->job_headers = all_headers;
331 job->aid_header = aid_header;
332
272 if ((CURLE_OK != curl_easy_setopt (eh, CURLOPT_PRIVATE, job)) || 333 if ((CURLE_OK != curl_easy_setopt (eh, CURLOPT_PRIVATE, job)) ||
273 (CURLE_OK != 334 (CURLE_OK !=
274 curl_easy_setopt (eh, CURLOPT_WRITEFUNCTION, &download_cb)) || 335 curl_easy_setopt (eh, CURLOPT_WRITEFUNCTION, &download_cb)) ||
@@ -308,6 +369,8 @@ GNUNET_CURL_job_cancel (struct GNUNET_CURL_Job *job)
308 curl_multi_remove_handle (ctx->multi, job->easy_handle)); 369 curl_multi_remove_handle (ctx->multi, job->easy_handle));
309 curl_easy_cleanup (job->easy_handle); 370 curl_easy_cleanup (job->easy_handle);
310 GNUNET_free_non_null (job->db.buf); 371 GNUNET_free_non_null (job->db.buf);
372 GNUNET_free_non_null (job->aid_header);
373 curl_slist_free_all (job->job_headers);
311 GNUNET_free (job); 374 GNUNET_free (job);
312} 375}
313 376
@@ -401,8 +464,8 @@ download_get_result (struct GNUNET_CURL_DownloadBuffer *db,
401int 464int
402GNUNET_CURL_append_header (struct GNUNET_CURL_Context *ctx, const char *header) 465GNUNET_CURL_append_header (struct GNUNET_CURL_Context *ctx, const char *header)
403{ 466{
404 ctx->json_header = curl_slist_append (ctx->json_header, header); 467 ctx->common_headers = curl_slist_append (ctx->common_headers, header);
405 if (NULL == ctx->json_header) 468 if (NULL == ctx->common_headers)
406 return GNUNET_SYSERR; 469 return GNUNET_SYSERR;
407 470
408 return GNUNET_OK; 471 return GNUNET_OK;
@@ -599,7 +662,7 @@ GNUNET_CURL_fini (struct GNUNET_CURL_Context *ctx)
599 GNUNET_assert (NULL == ctx->jobs_head); 662 GNUNET_assert (NULL == ctx->jobs_head);
600 curl_share_cleanup (ctx->share); 663 curl_share_cleanup (ctx->share);
601 curl_multi_cleanup (ctx->multi); 664 curl_multi_cleanup (ctx->multi);
602 curl_slist_free_all (ctx->json_header); 665 curl_slist_free_all (ctx->common_headers);
603 GNUNET_free (ctx); 666 GNUNET_free (ctx);
604} 667}
605 668
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
319 /* Followed by data. */ 319 /* Followed by data. */
320}; 320};
321 321
322
323/**
324 * Identifier for an asynchronous execution context.
325 */
326struct GNUNET_AsyncScopeId
327{
328 uint32_t bits[16 / sizeof (uint32_t)]; /* = 16 bytes */
329};
330
322GNUNET_NETWORK_STRUCT_END 331GNUNET_NETWORK_STRUCT_END
323 332
333
334/**
335 * Saved async scope identifier or root scope.
336 */
337struct GNUNET_AsyncScopeSave {
338 /**
339 * Saved scope. Unused if 'have_scope==GNUNET_NO'.
340 */
341 struct GNUNET_AsyncScopeId scope_id;
342
343 /**
344 * GNUNET_YES unless this saved scope is the unnamed root scope.
345 */
346 int have_scope;
347};
348
349
324/** 350/**
325 * Function called with a filename. 351 * Function called with a filename.
326 * 352 *
@@ -1331,6 +1357,44 @@ struct GNUNET_MessageHeader *
1331GNUNET_copy_message (const struct GNUNET_MessageHeader *msg); 1357GNUNET_copy_message (const struct GNUNET_MessageHeader *msg);
1332 1358
1333 1359
1360/**
1361 * Set the async scope for the current thread.
1362 *
1363 * @param aid the async scope identifier
1364 * @param old_scope[out] location to save the old scope
1365 */
1366void
1367GNUNET_async_scope_enter (const struct GNUNET_AsyncScopeId *aid,
1368 struct GNUNET_AsyncScopeSave *old_scope);
1369
1370
1371/**
1372 * Clear the current thread's async scope.
1373 *
1374 * @param old_scope scope to restore
1375 */
1376void
1377GNUNET_async_scope_restore (struct GNUNET_AsyncScopeSave *old_scope);
1378
1379
1380/**
1381 * Get the current async scope.
1382 *
1383 * @param[out] scope_ret pointer to where the result is stored
1384 */
1385void
1386GNUNET_async_scope_get (struct GNUNET_AsyncScopeSave *scope_ret);
1387
1388
1389/**
1390 * Generate a fresh async scope identifier.
1391 *
1392 * @param[out] aid_ret pointer to where the result is stored
1393 */
1394void
1395GNUNET_async_scope_fresh (struct GNUNET_AsyncScopeId *aid_ret);
1396
1397
1334#if __STDC_VERSION__ < 199901L 1398#if __STDC_VERSION__ < 199901L
1335#if __GNUC__ >= 2 1399#if __GNUC__ >= 2
1336#define __func__ __FUNCTION__ 1400#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
294GNUNET_CURL_gnunet_scheduler_reschedule (void *cls); 294GNUNET_CURL_gnunet_scheduler_reschedule (void *cls);
295 295
296 296
297/**
298 * Enable sending the async scope ID as a header.
299 *
300 * @param ctx the context to enable this for
301 * @param header_name name of the header to send.
302 */
303void
304GNUNET_CURL_enable_async_scope_header (struct GNUNET_CURL_Context *ctx, const char *header_name);
305
306
297#endif 307#endif
298/** @} */ /* end of group */ 308/** @} */ /* end of group */
299 309
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
214}; 214};
215 215
216 216
217
218
217/** 219/**
218 * Function used by event-loop implementations to signal the scheduler 220 * Function used by event-loop implementations to signal the scheduler
219 * that a particular @a task is ready due to an event specified in the 221 * 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,
904 void *new_select_cls); 906 void *new_select_cls);
905 907
906 908
909
910/**
911 * Change the async scope for the currently executing task and (transitively)
912 * for all tasks scheduled by the current task after calling this function.
913 * Nested tasks can begin their own nested async scope.
914 *
915 * Once the current task is finished, the async scope ID is reset to
916 * its previous value.
917 *
918 * Must only be called from a running task.
919 *
920 * @param aid the asynchronous scope id to enter
921 */
922void
923GNUNET_SCHEDULER_begin_async_scope (struct GNUNET_AsyncScopeId *aid);
924
925
926
907#if 0 /* keep Emacsens' auto-indent happy */ 927#if 0 /* keep Emacsens' auto-indent happy */
908{ 928{
909#endif 929#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
95 void *logger_cls; 95 void *logger_cls;
96}; 96};
97 97
98
99/**
100 * Asynchronous scope of the current thread, or NULL if we have not
101 * entered an async scope yet.
102 */
103static __thread struct GNUNET_AsyncScopeSave current_async_scope;
104
98/** 105/**
99 * The last "bulk" error message that we have been logging. 106 * The last "bulk" error message that we have been logging.
100 * Note that this message maybe truncated to the first BULK_TRACK_SIZE 107 * Note that this message maybe truncated to the first BULK_TRACK_SIZE
@@ -838,6 +845,28 @@ output_message (enum GNUNET_ErrorType kind,
838 "* %s", 845 "* %s",
839 msg); 846 msg);
840 } 847 }
848 else if (GNUNET_YES == current_async_scope.have_scope)
849 {
850 static GNUNET_THREAD_LOCAL char id_buf[27];
851 char *end;
852
853 /* We're logging, so skip_log must be currently 0. */
854 skip_log = 100;
855 end = GNUNET_STRINGS_data_to_string (&current_async_scope.scope_id,
856 sizeof (struct GNUNET_AsyncScopeId),
857 id_buf,
858 sizeof (id_buf) - 1);
859 GNUNET_assert (NULL != end);
860 *end = '\0';
861 skip_log = 0;
862 FPRINTF (GNUNET_stderr,
863 "%s %s(%s) %s %s",
864 datestr,
865 comp,
866 id_buf,
867 GNUNET_error_type_to_string (kind),
868 msg);
869 }
841 else 870 else
842 { 871 {
843 FPRINTF (GNUNET_stderr, 872 FPRINTF (GNUNET_stderr,
@@ -1548,6 +1577,60 @@ GNUNET_log_config_invalid (enum GNUNET_ErrorType kind,
1548 1577
1549 1578
1550/** 1579/**
1580 * Set the async scope for the current thread.
1581 *
1582 * @param aid the async scope identifier
1583 * @param old_scope[out] location to save the old scope
1584 */
1585void
1586GNUNET_async_scope_enter (const struct GNUNET_AsyncScopeId *aid,
1587 struct GNUNET_AsyncScopeSave *old_scope)
1588{
1589 *old_scope = current_async_scope;
1590 current_async_scope.have_scope = GNUNET_YES;
1591 current_async_scope.scope_id = *aid;
1592}
1593
1594
1595/**
1596 * Clear the current thread's async scope.
1597 *
1598 * @param old_scope scope to restore
1599 */
1600void
1601GNUNET_async_scope_restore (struct GNUNET_AsyncScopeSave *old_scope)
1602{
1603 current_async_scope = *old_scope;
1604}
1605
1606
1607/**
1608 * Generate a fresh async scope identifier.
1609 *
1610 * @param[out] aid_ret pointer to where the result is stored
1611 */
1612void
1613GNUNET_async_scope_fresh (struct GNUNET_AsyncScopeId *aid_ret)
1614{
1615 GNUNET_CRYPTO_random_block (GNUNET_CRYPTO_QUALITY_WEAK,
1616 aid_ret,
1617 sizeof (struct GNUNET_AsyncScopeId));
1618}
1619
1620
1621/**
1622 * Get the current async scope.
1623 *
1624 * @param[out] scope_ret pointer to where the result is stored
1625 */
1626void
1627GNUNET_async_scope_get (struct GNUNET_AsyncScopeSave *scope_ret)
1628{
1629 *scope_ret = current_async_scope;
1630}
1631
1632
1633/**
1551 * Initializer 1634 * Initializer
1552 */ 1635 */
1553void __attribute__ ((constructor)) 1636void __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
241 int num_backtrace_strings; 241 int num_backtrace_strings;
242#endif 242#endif
243 243
244 /**
245 * Asynchronous scope of the task that scheduled this scope,
246 */
247 struct GNUNET_AsyncScopeSave scope;
248
244}; 249};
245 250
246 251
@@ -1105,6 +1110,7 @@ GNUNET_SCHEDULER_add_at_with_priority (struct GNUNET_TIME_Absolute at,
1105 GNUNET_assert (NULL != scheduler_driver); 1110 GNUNET_assert (NULL != scheduler_driver);
1106 GNUNET_assert (NULL != task); 1111 GNUNET_assert (NULL != task);
1107 t = GNUNET_new (struct GNUNET_SCHEDULER_Task); 1112 t = GNUNET_new (struct GNUNET_SCHEDULER_Task);
1113 GNUNET_async_scope_get (&t->scope);
1108 t->callback = task; 1114 t->callback = task;
1109 t->callback_cls = task_cls; 1115 t->callback_cls = task_cls;
1110 t->read_fd = -1; 1116 t->read_fd = -1;
@@ -1293,6 +1299,7 @@ GNUNET_SCHEDULER_add_shutdown (GNUNET_SCHEDULER_TaskCallback task,
1293 GNUNET_assert (NULL != scheduler_driver); 1299 GNUNET_assert (NULL != scheduler_driver);
1294 GNUNET_assert (NULL != task); 1300 GNUNET_assert (NULL != task);
1295 t = GNUNET_new (struct GNUNET_SCHEDULER_Task); 1301 t = GNUNET_new (struct GNUNET_SCHEDULER_Task);
1302 GNUNET_async_scope_get (&t->scope);
1296 t->callback = task; 1303 t->callback = task;
1297 t->callback_cls = task_cls; 1304 t->callback_cls = task_cls;
1298 t->read_fd = -1; 1305 t->read_fd = -1;
@@ -1411,6 +1418,7 @@ add_without_sets (struct GNUNET_TIME_Relative delay,
1411 GNUNET_assert (NULL != scheduler_driver); 1418 GNUNET_assert (NULL != scheduler_driver);
1412 GNUNET_assert (NULL != task); 1419 GNUNET_assert (NULL != task);
1413 t = GNUNET_new (struct GNUNET_SCHEDULER_Task); 1420 t = GNUNET_new (struct GNUNET_SCHEDULER_Task);
1421 GNUNET_async_scope_get (&t->scope);
1414 init_fd_info (t, 1422 init_fd_info (t,
1415 &read_nh, 1423 &read_nh,
1416 read_nh ? 1 : 0, 1424 read_nh ? 1 : 0,
@@ -1882,6 +1890,7 @@ GNUNET_SCHEDULER_add_select (enum GNUNET_SCHEDULER_Priority prio,
1882 task, 1890 task,
1883 task_cls); 1891 task_cls);
1884 t = GNUNET_new (struct GNUNET_SCHEDULER_Task); 1892 t = GNUNET_new (struct GNUNET_SCHEDULER_Task);
1893 GNUNET_async_scope_get (&t->scope);
1885 init_fd_info (t, 1894 init_fd_info (t,
1886 read_nhandles, 1895 read_nhandles,
1887 read_nhandles_len, 1896 read_nhandles_len,
@@ -2114,7 +2123,15 @@ GNUNET_SCHEDULER_do_work (struct GNUNET_SCHEDULER_Handle *sh)
2114 "Running task %p\n", 2123 "Running task %p\n",
2115 pos); 2124 pos);
2116 GNUNET_assert (NULL != pos->callback); 2125 GNUNET_assert (NULL != pos->callback);
2117 pos->callback (pos->callback_cls); 2126 {
2127 struct GNUNET_AsyncScopeSave old_scope;
2128 if (pos->scope.have_scope)
2129 GNUNET_async_scope_enter (&pos->scope.scope_id, &old_scope);
2130 else
2131 GNUNET_async_scope_get (&old_scope);
2132 pos->callback (pos->callback_cls);
2133 GNUNET_async_scope_restore (&old_scope);
2134 }
2118 if (NULL != pos->fds) 2135 if (NULL != pos->fds)
2119 { 2136 {
2120 int del_result = scheduler_driver->del (scheduler_driver->cls, pos); 2137 int del_result = scheduler_driver->del (scheduler_driver->cls, pos);
@@ -2513,4 +2530,28 @@ GNUNET_SCHEDULER_driver_select ()
2513} 2530}
2514 2531
2515 2532
2533/**
2534 * Change the async scope for the currently executing task and (transitively)
2535 * for all tasks scheduled by the current task after calling this function.
2536 * Nested tasks can begin their own nested async scope.
2537 *
2538 * Once the current task is finished, the async scope ID is reset to
2539 * its previous value.
2540 *
2541 * Must only be called from a running task.
2542 *
2543 * @param aid the asynchronous scope id to enter
2544 */
2545void
2546GNUNET_SCHEDULER_begin_async_scope (struct GNUNET_AsyncScopeId *aid)
2547{
2548 struct GNUNET_AsyncScopeSave dummy_old_scope;
2549
2550 GNUNET_assert (NULL != active_task);
2551 /* Since we're in a task, the context will be automatically
2552 restored by the scheduler. */
2553 GNUNET_async_scope_enter (aid, &dummy_old_scope);
2554}
2555
2556
2516/* end of scheduler.c */ 2557/* end of scheduler.c */