glib/tests/logging.c

   1 #include <stdlib.h>
   2 #include <string.h>
   3 #define G_LOG_USE_STRUCTURED 1
   4 #include <glib.h>
   5
   6 /* Test g_warn macros */
   7 static void
   8 test_warnings (void)
   9 {
  10   g_test_expect_message (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING,
  11                          "*test_warnings*should not be reached*");
  12   g_warn_if_reached ();
  13   g_test_assert_expected_messages ();
  14
  15   g_test_expect_message (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING,
  16                          "*test_warnings*runtime check failed*");
  17   g_warn_if_fail (FALSE);
  18   g_test_assert_expected_messages ();
  19 }
  20
  21 static guint log_count = 0;
  22
  23 static void
  24 log_handler (const gchar    *log_domain,
  25              GLogLevelFlags  log_level,
  26              const gchar    *message,
  27              gpointer        user_data)
  28 {
  29   g_assert_cmpstr (log_domain, ==, "bu");
  30   g_assert_cmpint (log_level, ==, G_LOG_LEVEL_INFO);
  31
  32   log_count++;
  33 }
  34
  35 /* test that custom log handlers only get called for
  36  * their domain and level
  37  */
  38 static void
  39 test_set_handler (void)
  40 {
  41   guint id;
  42
  43   id = g_log_set_handler ("bu", G_LOG_LEVEL_INFO, log_handler, NULL);
  44
  45   g_log ("bu", G_LOG_LEVEL_DEBUG, "message");
  46   g_log ("ba", G_LOG_LEVEL_DEBUG, "message");
  47   g_log ("bu", G_LOG_LEVEL_INFO, "message");
  48   g_log ("ba", G_LOG_LEVEL_INFO, "message");
  49
  50   g_assert_cmpint (log_count, ==, 1);
  51
  52   g_log_remove_handler ("bu", id);
  53 }
  54
  55 static void
  56 test_default_handler_error (void)
  57 {
  58   g_log_set_default_handler (g_log_default_handler, NULL);
  59   g_error ("message1");
  60   exit (0);
  61 }
  62
  63 static void
  64 test_default_handler_critical (void)
  65 {
  66   g_log_set_default_handler (g_log_default_handler, NULL);
  67   g_critical ("message2");
  68   exit (0);
  69 }
  70
  71 static void
  72 test_default_handler_warning (void)
  73 {
  74   g_log_set_default_handler (g_log_default_handler, NULL);
  75   g_warning ("message3");
  76   exit (0);
  77 }
  78
  79 static void
  80 test_default_handler_message (void)
  81 {
  82   g_log_set_default_handler (g_log_default_handler, NULL);
  83   g_message ("message4");
  84   exit (0);
  85 }
  86
  87 static void
  88 test_default_handler_info (void)
  89 {
  90   g_log_set_default_handler (g_log_default_handler, NULL);
  91   g_log (G_LOG_DOMAIN, G_LOG_LEVEL_INFO, "message5");
  92   exit (0);
  93 }
  94
  95 static void
  96 test_default_handler_bar_info (void)
  97 {
  98   g_log_set_default_handler (g_log_default_handler, NULL);
  99
 100   g_setenv ("G_MESSAGES_DEBUG", "foo bar baz", TRUE);
 101
 102   g_log ("bar", G_LOG_LEVEL_INFO, "message5");
 103   exit (0);
 104 }
 105
 106 static void
 107 test_default_handler_baz_debug (void)
 108 {
 109   g_log_set_default_handler (g_log_default_handler, NULL);
 110
 111   g_setenv ("G_MESSAGES_DEBUG", "foo bar baz", TRUE);
 112
 113   g_log ("baz", G_LOG_LEVEL_DEBUG, "message6");
 114   exit (0);
 115 }
 116
 117 static void
 118 test_default_handler_debug (void)
 119 {
 120   g_log_set_default_handler (g_log_default_handler, NULL);
 121
 122   g_setenv ("G_MESSAGES_DEBUG", "all", TRUE);
 123
 124   g_log ("foo", G_LOG_LEVEL_DEBUG, "6");
 125   g_log ("bar", G_LOG_LEVEL_DEBUG, "6");
 126   g_log ("baz", G_LOG_LEVEL_DEBUG, "6");
 127   exit (0);
 128 }
 129
 130 static void
 131 test_default_handler_0x400 (void)
 132 {
 133   g_log_set_default_handler (g_log_default_handler, NULL);
 134   g_log (G_LOG_DOMAIN, 1<<10, "message7");
 135   exit (0);
 136 }
 137
 138 static void
 139 test_default_handler (void)
 140 {
 141   g_test_trap_subprocess ("/logging/default-handler/subprocess/error", 0, 0);
 142   g_test_trap_assert_failed ();
 143   g_test_trap_assert_stderr ("*ERROR*message1*");
 144
 145   g_test_trap_subprocess ("/logging/default-handler/subprocess/critical", 0, 0);
 146   g_test_trap_assert_failed ();
 147   g_test_trap_assert_stderr ("*CRITICAL*message2*");
 148
 149   g_test_trap_subprocess ("/logging/default-handler/subprocess/warning", 0, 0);
 150   g_test_trap_assert_failed ();
 151   g_test_trap_assert_stderr ("*WARNING*message3*");
 152
 153   g_test_trap_subprocess ("/logging/default-handler/subprocess/message", 0, 0);
 154   g_test_trap_assert_passed ();
 155   g_test_trap_assert_stderr ("*Message*message4*");
 156
 157   g_test_trap_subprocess ("/logging/default-handler/subprocess/info", 0, 0);
 158   g_test_trap_assert_passed ();
 159   g_test_trap_assert_stdout_unmatched ("*INFO*message5*");
 160
 161   g_test_trap_subprocess ("/logging/default-handler/subprocess/bar-info", 0, 0);
 162   g_test_trap_assert_passed ();
 163   g_test_trap_assert_stdout ("*INFO*message5*");
 164
 165   g_test_trap_subprocess ("/logging/default-handler/subprocess/baz-debug", 0, 0);
 166   g_test_trap_assert_passed ();
 167   g_test_trap_assert_stdout ("*DEBUG*message6*");
 168
 169   g_test_trap_subprocess ("/logging/default-handler/subprocess/debug", 0, 0);
 170   g_test_trap_assert_passed ();
 171   g_test_trap_assert_stdout ("*DEBUG*6*6*6*");
 172
 173   g_test_trap_subprocess ("/logging/default-handler/subprocess/0x400", 0, 0);
 174   g_test_trap_assert_passed ();
 175   g_test_trap_assert_stdout ("*LOG-0x400*message7*");
 176 }
 177
 178 static void
 179 test_fatal_log_mask (void)
 180 {
 181   if (g_test_subprocess ())
 182     {
 183       g_log_set_fatal_mask ("bu", G_LOG_LEVEL_INFO);
 184       g_log ("bu", G_LOG_LEVEL_INFO, "fatal");
 185       return;
 186     }
 187   g_test_trap_subprocess (NULL, 0, 0);
 188   g_test_trap_assert_failed ();
 189   /* G_LOG_LEVEL_INFO isn't printed by default */
 190   g_test_trap_assert_stdout_unmatched ("*fatal*");
 191 }
 192
 193 static gint my_print_count = 0;
 194 static void
 195 my_print_handler (const gchar *text)
 196 {
 197   my_print_count++;
 198 }
 199
 200 static void
 201 test_print_handler (void)
 202 {
 203   GPrintFunc old_print_handler;
 204
 205   old_print_handler = g_set_print_handler (my_print_handler);
 206   g_assert (old_print_handler == NULL);
 207
 208   my_print_count = 0;
 209   g_print ("bu ba");
 210   g_assert_cmpint (my_print_count, ==, 1);
 211
 212   g_set_print_handler (NULL);
 213 }
 214
 215 static void
 216 test_printerr_handler (void)
 217 {
 218   GPrintFunc old_printerr_handler;
 219
 220   old_printerr_handler = g_set_printerr_handler (my_print_handler);
 221   g_assert (old_printerr_handler == NULL);
 222
 223   my_print_count = 0;
 224   g_printerr ("bu ba");
 225   g_assert_cmpint (my_print_count, ==, 1);
 226
 227   g_set_printerr_handler (NULL);
 228 }
 229
 230 static char *fail_str = "foo";
 231 static char *log_str = "bar";
 232
 233 static gboolean
 234 good_failure_handler (const gchar    *log_domain,
 235                       GLogLevelFlags  log_level,
 236                       const gchar    *msg,
 237                       gpointer        user_data)
 238 {
 239   g_test_message ("The Good Fail Message Handler\n");
 240   g_assert ((char *)user_data != log_str);
 241   g_assert ((char *)user_data == fail_str);
 242
 243   return FALSE;
 244 }
 245
 246 static gboolean
 247 bad_failure_handler (const gchar    *log_domain,
 248                      GLogLevelFlags  log_level,
 249                      const gchar    *msg,
 250                      gpointer        user_data)
 251 {
 252   g_test_message ("The Bad Fail Message Handler\n");
 253   g_assert ((char *)user_data == log_str);
 254   g_assert ((char *)user_data != fail_str);
 255
 256   return FALSE;
 257 }
 258
 259 static void
 260 test_handler (const gchar    *log_domain,
 261               GLogLevelFlags  log_level,
 262               const gchar    *msg,
 263               gpointer        user_data)
 264 {
 265   g_test_message ("The Log Message Handler\n");
 266   g_assert ((char *)user_data != fail_str);
 267   g_assert ((char *)user_data == log_str);
 268 }
 269
 270 static void
 271 bug653052 (void)
 272 {
 273   g_test_bug ("653052");
 274
 275   g_test_log_set_fatal_handler (good_failure_handler, fail_str);
 276   g_log_set_default_handler (test_handler, log_str);
 277
 278   g_return_if_fail (0);
 279
 280   g_test_log_set_fatal_handler (bad_failure_handler, fail_str);
 281   g_log_set_default_handler (test_handler, log_str);
 282
 283   g_return_if_fail (0);
 284 }
 285
 286 static void
 287 test_gibberish (void)
 288 {
 289   if (g_test_subprocess ())
 290     {
 291       g_warning ("bla bla \236\237\190");
 292       return;
 293     }
 294   g_test_trap_subprocess (NULL, 0, 0);
 295   g_test_trap_assert_failed ();
 296   g_test_trap_assert_stderr ("*bla bla \\x9e\\x9f\\u000190*");
 297 }
 298
 299 static GLogWriterOutput
 300 null_log_writer (GLogLevelFlags   log_level,
 301                  const GLogField *fields,
 302                  gsize            n_fields,
 303                  gpointer         user_data)
 304 {
 305   log_count++;
 306   return G_LOG_WRITER_HANDLED;
 307 }
 308
 309 typedef struct {
 310   const GLogField *fields;
 311   gsize n_fields;
 312 } ExpectedMessage;
 313
 314 static gboolean
 315 compare_field (const GLogField *f1, const GLogField *f2)
 316 {
 317   if (strcmp (f1->key, f2->key) != 0)
 318     return FALSE;
 319   if (f1->length != f2->length)
 320     return FALSE;
 321
 322   if (f1->length == -1)
 323     return strcmp (f1->value, f2->value) == 0;
 324   else
 325     return memcmp (f1->value, f2->value, f1->length) == 0;
 326 }
 327
 328 static gboolean
 329 compare_fields (const GLogField *f1, gsize n1, const GLogField *f2, gsize n2)
 330 {
 331   int i, j;
 332
 333   for (i = 0; i < n1; i++)
 334     {
 335       for (j = 0; j < n2; j++)
 336         {
 337           if (compare_field (&f1[i], &f2[j]))
 338             break;
 339         }
 340       if (j == n2)
 341         return FALSE;
 342     }
 343
 344   return TRUE;
 345 }
 346
 347 static GSList *expected_messages = NULL;
 348 static const guchar binary_field[] = {1, 2, 3, 4, 5};
 349
 350
 351 static GLogWriterOutput
 352 expect_log_writer (GLogLevelFlags   log_level,
 353                    const GLogField *fields,
 354                    gsize            n_fields,
 355                    gpointer         user_data)
 356 {
 357   ExpectedMessage *expected = expected_messages->data;
 358
 359   if (compare_fields (fields, n_fields, expected->fields, expected->n_fields))
 360     {
 361       expected_messages = g_slist_delete_link (expected_messages, expected_messages);
 362     }
 363   else if ((log_level & G_LOG_LEVEL_DEBUG) != G_LOG_LEVEL_DEBUG)
 364     {
 365       char *str;
 366
 367       str = g_log_writer_format_fields (log_level, fields, n_fields, FALSE);
 368       g_test_message ("Unexpected message: %s", str);
 369       g_free (str);
 370       g_test_fail ();
 371     }
 372
 373   return G_LOG_WRITER_HANDLED;
 374 }
 375
 376 static void
 377 test_structured_logging_no_state (void)
 378 {
 379   gpointer some_pointer = GUINT_TO_POINTER (0x100);
 380   guint some_integer = 123;
 381
 382   log_count = 0;
 383   g_log_set_writer_func (null_log_writer, NULL, NULL);
 384
 385   g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE,
 386                     "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e",
 387                     "MY_APPLICATION_CUSTOM_FIELD", "some debug string",
 388                     "MESSAGE", "This is a debug message about pointer %p and integer %u.",
 389                     some_pointer, some_integer);
 390
 391   g_assert_cmpint (log_count, ==, 1);
 392 }
 393
 394 static void
 395 test_structured_logging_some_state (void)
 396 {
 397   gpointer state_object = NULL;  /* this must not be dereferenced */
 398   const GLogField fields[] = {
 399     { "MESSAGE", "This is a debug message.", -1 },
 400     { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 },
 401     { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 },
 402     { "MY_APPLICATION_STATE", state_object, 0 },
 403   };
 404
 405   log_count = 0;
 406   g_log_set_writer_func (null_log_writer, NULL, NULL);
 407
 408   g_log_structured_array (G_LOG_LEVEL_DEBUG, fields, G_N_ELEMENTS (fields));
 409
 410   g_assert_cmpint (log_count, ==, 1);
 411 }
 412
 413 static void
 414 test_structured_logging_robustness (void)
 415 {
 416   log_count = 0;
 417   g_log_set_writer_func (null_log_writer, NULL, NULL);
 418
 419   /* NULL log_domain shouldn't crash */
 420   g_log (NULL, G_LOG_LEVEL_MESSAGE, "Test");
 421   g_log_structured (NULL, G_LOG_LEVEL_MESSAGE, "MESSAGE", "Test");
 422
 423   g_assert_cmpint (log_count, ==, 1);
 424 }
 425
 426 static void
 427 test_structured_logging_roundtrip1 (void)
 428 {
 429   gpointer some_pointer = GUINT_TO_POINTER (0x100);
 430   gint some_integer = 123;
 431   gchar message[200];
 432   GLogField fields[] = {
 433     { "GLIB_DOMAIN", "some-domain", -1 },
 434     { "PRIORITY", "5", -1 },
 435     { "MESSAGE", "String assigned using g_snprintf() below", -1 },
 436     { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 },
 437     { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 }
 438   };
 439   ExpectedMessage expected = { fields, 5 };
 440
 441   /* %p format is implementation defined and depends on the platform */
 442   g_snprintf (message, sizeof (message),
 443               "This is a debug message about pointer %p and integer %u.",
 444               some_pointer, some_integer);
 445   fields[2].value = message;
 446
 447   expected_messages = g_slist_append (NULL, &expected);
 448   g_log_set_writer_func (expect_log_writer, NULL, NULL);
 449
 450   g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE,
 451                     "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893",
 452                     "MY_APPLICATION_CUSTOM_FIELD", "some debug string",
 453                     "MESSAGE", "This is a debug message about pointer %p and integer %u.",
 454                     some_pointer, some_integer);
 455
 456   if (expected_messages != NULL)
 457     {
 458       char *str;
 459       ExpectedMessage *expected = expected_messages->data;
 460
 461       str = g_log_writer_format_fields (0, expected->fields, expected->n_fields, FALSE);
 462       g_test_message ("Unexpected message: %s", str);
 463       g_free (str);
 464       g_test_fail ();
 465     }
 466 }
 467
 468 static void
 469 test_structured_logging_roundtrip2 (void)
 470 {
 471   const gchar *some_string = "abc";
 472   const GLogField fields[] = {
 473     { "GLIB_DOMAIN", "some-domain", -1 },
 474     { "PRIORITY", "5", -1 },
 475     { "MESSAGE", "This is a debug message about string 'abc'.", -1 },
 476     { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 },
 477     { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 }
 478   };
 479   ExpectedMessage expected = { fields, 5 };
 480
 481   expected_messages = g_slist_append (NULL, &expected);
 482   g_log_set_writer_func (expect_log_writer, NULL, NULL);
 483
 484   g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE,
 485                     "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893",
 486                     "MY_APPLICATION_CUSTOM_FIELD", "some debug string",
 487                     "MESSAGE", "This is a debug message about string '%s'.",
 488                     some_string);
 489
 490   g_assert (expected_messages == NULL);
 491 }
 492
 493 static void
 494 test_structured_logging_roundtrip3 (void)
 495 {
 496   const GLogField fields[] = {
 497     { "GLIB_DOMAIN", "some-domain", -1 },
 498     { "PRIORITY", "4", -1 },
 499     { "MESSAGE", "Test test test.", -1 }
 500   };
 501   ExpectedMessage expected = { fields, 3 };
 502
 503   expected_messages = g_slist_append (NULL, &expected);
 504   g_log_set_writer_func (expect_log_writer, NULL, NULL);
 505
 506   g_log_structured ("some-domain", G_LOG_LEVEL_WARNING,
 507                     "MESSAGE", "Test test test.");
 508
 509   g_assert (expected_messages == NULL);
 510 }
 511
 512 static GVariant *
 513 create_variant_fields (void)
 514 {
 515   GVariant *binary;
 516   GVariantBuilder builder;
 517
 518   binary = g_variant_new_fixed_array (G_VARIANT_TYPE_BYTE, binary_field, G_N_ELEMENTS (binary_field), sizeof (binary_field[0]));
 519
 520   g_variant_builder_init (&builder, G_VARIANT_TYPE ("a{sv}"));
 521   g_variant_builder_add (&builder, "{sv}", "MESSAGE_ID", g_variant_new_string ("06d4df59e6c24647bfe69d2c27ef0b4e"));
 522   g_variant_builder_add (&builder, "{sv}", "MESSAGE", g_variant_new_string ("This is a debug message"));
 523   g_variant_builder_add (&builder, "{sv}", "MY_APPLICATION_CUSTOM_FIELD", g_variant_new_string ("some debug string"));
 524   g_variant_builder_add (&builder, "{sv}", "MY_APPLICATION_CUSTOM_FIELD_BINARY", binary);
 525
 526   return g_variant_builder_end (&builder);
 527 }
 528
 529 static void
 530 test_structured_logging_variant1 (void)
 531 {
 532   GVariant *v = create_variant_fields ();
 533
 534   log_count = 0;
 535   g_log_set_writer_func (null_log_writer, NULL, NULL);
 536
 537   g_log_variant ("some-domain", G_LOG_LEVEL_MESSAGE, v);
 538   g_variant_unref (v);
 539   g_assert_cmpint (log_count, ==, 1);
 540 }
 541
 542 static void
 543 test_structured_logging_variant2 (void)
 544 {
 545   const GLogField fields[] = {
 546     { "GLIB_DOMAIN", "some-domain", -1 },
 547     { "PRIORITY", "5", -1 },
 548     { "MESSAGE", "This is a debug message", -1 },
 549     { "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e", -1 },
 550     { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 },
 551     { "MY_APPLICATION_CUSTOM_FIELD_BINARY", binary_field, sizeof (binary_field) }
 552   };
 553   ExpectedMessage expected = { fields, 6 };
 554   GVariant *v = create_variant_fields ();
 555
 556   expected_messages = g_slist_append (NULL, &expected);
 557   g_log_set_writer_func (expect_log_writer, NULL, NULL);
 558
 559   g_log_variant ("some-domain", G_LOG_LEVEL_MESSAGE, v);
 560   g_variant_unref (v);
 561   g_assert (expected_messages == NULL);
 562 }
 563
 564 int
 565 main (int argc, char *argv[])
 566 {
 567   g_unsetenv ("G_MESSAGES_DEBUG");
 568
 569   g_test_init (&argc, &argv, NULL);
 570   g_test_bug_base ("http://bugzilla.gnome.org/");
 571
 572   g_test_add_func ("/logging/default-handler", test_default_handler);
 573   g_test_add_func ("/logging/default-handler/subprocess/error", test_default_handler_error);
 574   g_test_add_func ("/logging/default-handler/subprocess/critical", test_default_handler_critical);
 575   g_test_add_func ("/logging/default-handler/subprocess/warning", test_default_handler_warning);
 576   g_test_add_func ("/logging/default-handler/subprocess/message", test_default_handler_message);
 577   g_test_add_func ("/logging/default-handler/subprocess/info", test_default_handler_info);
 578   g_test_add_func ("/logging/default-handler/subprocess/bar-info", test_default_handler_bar_info);
 579   g_test_add_func ("/logging/default-handler/subprocess/baz-debug", test_default_handler_baz_debug);
 580   g_test_add_func ("/logging/default-handler/subprocess/debug", test_default_handler_debug);
 581   g_test_add_func ("/logging/default-handler/subprocess/0x400", test_default_handler_0x400);
 582   g_test_add_func ("/logging/warnings", test_warnings);
 583   g_test_add_func ("/logging/fatal-log-mask", test_fatal_log_mask);
 584   g_test_add_func ("/logging/set-handler", test_set_handler);
 585   g_test_add_func ("/logging/print-handler", test_print_handler);
 586   g_test_add_func ("/logging/printerr-handler", test_printerr_handler);
 587   g_test_add_func ("/logging/653052", bug653052);
 588   g_test_add_func ("/logging/gibberish", test_gibberish);
 589   g_test_add_func ("/structured-logging/no-state", test_structured_logging_no_state);
 590   g_test_add_func ("/structured-logging/some-state", test_structured_logging_some_state);
 591   g_test_add_func ("/structured-logging/robustness", test_structured_logging_robustness);
 592   g_test_add_func ("/structured-logging/roundtrip1", test_structured_logging_roundtrip1);
 593   g_test_add_func ("/structured-logging/roundtrip2", test_structured_logging_roundtrip2);
 594   g_test_add_func ("/structured-logging/roundtrip3", test_structured_logging_roundtrip3);
 595   g_test_add_func ("/structured-logging/variant1", test_structured_logging_variant1);
 596   g_test_add_func ("/structured-logging/variant2", test_structured_logging_variant2);
 597
 598   return g_test_run ();
 599 }