src/util/test_common_logging_runtime_loglevels.c

   1 /*
   2      This file is part of GNUnet.
   3      Copyright (C) 2011 GNUnet e.V.
   4
   5      GNUnet is free software: you can redistribute it and/or modify it
   6      under the terms of the GNU Affero General Public License as published
   7      by the Free Software Foundation, either version 3 of the License,
   8      or (at your option) any later version.
   9
  10      GNUnet is distributed in the hope that it will be useful, but
  11      WITHOUT ANY WARRANTY; without even the implied warranty of
  12      MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  13      Affero General Public License for more details.
  14 */
  15
  16 /**
  17  * @file util/test_common_logging_runtime_loglevels.c
  18  * @brief testcase for the logging module  (runtime log level adjustment)
  19  * @author LRN
  20  */
  21 #include "platform.h"
  22 #include "gnunet_util_lib.h"
  23
  24 #define VERBOSE GNUNET_NO
  25
  26 /**
  27  * How much time the child is allowed to waste on skipped log calls, at most.
  28  * Raspberry Pi takes 113 microseconds tops, this is 3x that value.
  29  */
  30 #define MAX_SKIP_DELAY GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_MICROSECONDS, 400).rel_value_us
  31
  32 /**
  33  * How much time non-skipped log call should take, at least.
  34  * Keep in sync with the value in the dummy!
  35  */
  36 #define OUTPUT_DELAY GNUNET_TIME_relative_multiply (GNUNET_TIME_UNIT_MICROSECONDS, 1000).rel_value_us
  37
  38 static int ok;
  39
  40 static int phase = 0;
  41
  42 static struct GNUNET_OS_Process *proc;
  43
  44 /* Pipe to read from started processes stdout (on read end) */
  45 static struct GNUNET_DISK_PipeHandle *pipe_stdout;
  46
  47 static struct GNUNET_SCHEDULER_Task * die_task;
  48
  49 static struct GNUNET_SCHEDULER_Task * read_task;
  50
  51 static void
  52 runone (void);
  53
  54
  55 static void
  56 end_task (void *cls)
  57 {
  58   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Ending phase %d, ok is %d\n", phase,
  59               ok);
  60   if (NULL != proc)
  61   {
  62     if (0 != GNUNET_OS_process_kill (proc, GNUNET_TERM_SIG))
  63     {
  64       GNUNET_log_strerror (GNUNET_ERROR_TYPE_WARNING, "kill");
  65     }
  66     GNUNET_OS_process_wait (proc);
  67     GNUNET_OS_process_destroy (proc);
  68     proc = NULL;
  69   }
  70   if (NULL != read_task)
  71   {
  72     GNUNET_SCHEDULER_cancel (read_task);
  73     read_task = NULL;
  74   }
  75   GNUNET_DISK_pipe_close (pipe_stdout);
  76   if (ok == 1)
  77   {
  78     if (phase < 9)
  79     {
  80       phase += 1;
  81       runone ();
  82     }
  83     else
  84       ok = 0;
  85   }
  86   else
  87     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "failing\n");
  88 }
  89
  90
  91 static char *
  92 read_output_line (int phase_from1, int phase_to1, int phase_from2,
  93                   int phase_to2, char c, const char *expect_level,
  94                   long delay_morethan, long delay_lessthan, int phase,
  95                   char *p,
  96                   int *len, long *delay, char level[8])
  97 {
  98   char *r = p;
  99   char t[7];
 100   int i, j, stop = 0;
 101   int level_matches;
 102   int delay_is_sane;
 103   int delay_is_a_dummy;
 104   int delay_outside_of_range;
 105
 106   j = 0;
 107   int stage = 0;
 108
 109   if (!(phase >= phase_from1 && phase <= phase_to1) &&
 110       !(phase >= phase_from2 && phase <= phase_to2))
 111     return p;
 112 #if 0
 113   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
 114               "Trying to match '%c%s \\d\\r\\n' on %s\n", c, expect_level, p);
 115 #endif
 116   for (i = 0; i < *len && !stop; i++)
 117   {
 118     switch (stage)
 119     {
 120     case 0:                    /* read first char */
 121       if (r[i] != c)
 122       {
 123         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Expected '%c', but got '%c'\n", c,
 124                     r[i]);
 125         GNUNET_break (0);
 126         return NULL;
 127       }
 128       stage += 1;
 129       break;
 130     case 1:                    /* read at most 7 char-long error level string, finished by ' ' */
 131       if (r[i] == ' ')
 132       {
 133         level[j] = '\0';
 134         stage += 1;
 135         j = 0;
 136       }
 137       else if (i == 8)
 138       {
 139         GNUNET_break (0);
 140         ok = 2;
 141         return NULL;
 142       }
 143       else
 144         level[j++] = r[i];
 145       break;
 146     case 2:                    /* read the delay, finished by '\n' */
 147       t[j++] = r[i];
 148 #if WINDOWS
 149       if (r[i] == '\r' && r[i + 1] == '\n')
 150       {
 151         i += 1;
 152         t[j - 1] = '\0';
 153         *delay = strtol (t, NULL, 10);
 154         stop = 1;
 155       }
 156 #else
 157       if (r[i] == '\n')
 158       {
 159         t[j - 1] = '\0';
 160         *delay = strtol (t, NULL, 10);
 161         stop = 1;
 162       }
 163 #endif
 164       break;
 165     }
 166   }
 167   level_matches = (strcmp (expect_level, level) == 0);
 168   delay_is_sane = (*delay >= 0) && (*delay <= 1000000);
 169   delay_is_a_dummy = (c == 'L');
 170   /* Delay must be either less than 'lessthan' (log call is skipped)
 171    * or more than 'morethan' (log call is not skipped)
 172    */
 173   delay_outside_of_range = ((*delay < delay_lessthan) || (*delay >= delay_morethan));
 174   if (delay_is_a_dummy)
 175     delay_outside_of_range = 1;
 176
 177   if (! stop)
 178     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 179                 "Wrong log format?\n");
 180   if (! level_matches)
 181     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 182                 "Wrong log level\n");
 183   if (! delay_is_sane)
 184     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 185                 "Delay %ld is insane\n",
 186                 *delay);
 187   if (! delay_outside_of_range)
 188     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 189                 "Delay %ld is not outside of range (%ld ; %ld)\n",
 190                 *delay,
 191                 delay_lessthan,
 192                 delay_morethan);
 193   if (!stop || !level_matches || !delay_is_sane || !delay_outside_of_range)
 194     return NULL;
 195   *len = *len - i;
 196   return &r[i];
 197 }
 198
 199 /**
 200  * Up to 8 non-skipped GNUNET_log() calls
 201  * + extra line with delay for each one
 202  */
 203 #define LOG_MAX_NUM_LINES (8 * 2)
 204 /**
 205  * Actual message is 17 chars at most
 206  */
 207 #define LOG_MAX_LINE_LENGTH (17)
 208
 209 #define LOG_BUFFER_SIZE LOG_MAX_NUM_LINES * LOG_MAX_LINE_LENGTH
 210
 211 static char buf[LOG_BUFFER_SIZE];
 212
 213 static char *buf_ptr;
 214
 215 static int bytes;
 216
 217
 218 static void
 219 read_call (void *cls)
 220 {
 221   const struct GNUNET_DISK_FileHandle *stdout_read_handle = cls;
 222   char level[8];
 223   long delay;
 224   long delays[8];
 225   int rd;
 226
 227   read_task = NULL;
 228   rd = GNUNET_DISK_file_read (stdout_read_handle, buf_ptr,
 229                               sizeof (buf) - bytes);
 230   if (rd > 0)
 231   {
 232     buf_ptr += rd;
 233     bytes += rd;
 234 #if VERBOSE
 235     FPRINTF (stderr, "got %d bytes, reading more\n", rd);
 236 #endif
 237     read_task = GNUNET_SCHEDULER_add_read_file (GNUNET_TIME_UNIT_FOREVER_REL,
 238                                                 stdout_read_handle,
 239                                                 &read_call,
 240                                                 (void*) stdout_read_handle);
 241     return;
 242   }
 243
 244 #if VERBOSE
 245   FPRINTF (stderr, "bytes is %d:%s\n", bytes, buf);
 246 #endif
 247
 248   /* +------CHILD OUTPUT--
 249    * |      SOFT     HARD
 250    * |    E W I D  E W I D
 251    * | 0E *        * *
 252    * | 1W * *      * *
 253    * P 2I * * *    * *
 254    * H 3D * * * *  * *
 255    * A
 256    * S 4E *        *
 257    * E 5W * *      * *
 258    * | 6I * * *    * * *
 259    * | 7D * * * *  * * * *
 260    * | 8  * *      * *
 261    * | 9  * *      * *
 262    */
 263   char *p = buf;
 264
 265   if (bytes == LOG_BUFFER_SIZE ||
 266       !(p =
 267         read_output_line (0, 3, 4, 9, 'L', "ERROR", -1,
 268                           1, phase, p,
 269                           &bytes, &delay, level)) ||
 270       !(p =
 271         read_output_line (0, 3, 4, 9, '1', "ERROR", OUTPUT_DELAY,
 272                           MAX_SKIP_DELAY, phase, p,
 273                           &bytes, &delays[0], level)) ||
 274       !(p =
 275         read_output_line (1, 3, 5, 9, 'L', "WARNING", -1,
 276                           1, phase, p,
 277                           &bytes, &delay, level)) ||
 278       !(p =
 279         read_output_line (0, 3, 4, 9, '1', "WARNING", OUTPUT_DELAY,
 280                           MAX_SKIP_DELAY, phase, p,
 281                           &bytes, &delays[1], level)) ||
 282       !(p =
 283         read_output_line (2, 3, 6, 7, 'L', "INFO", -1,
 284                           1, phase, p,
 285                           &bytes, &delay, level)) ||
 286       !(p =
 287         read_output_line (0, 3, 4, 9, '1', "INFO", OUTPUT_DELAY,
 288                           MAX_SKIP_DELAY, phase, p,
 289                           &bytes, &delays[2], level)) ||
 290       !(p =
 291         read_output_line (3, 3, 7, 7, 'L', "DEBUG", -1,
 292                           1, phase, p,
 293                           &bytes, &delay, level)) ||
 294       !(p =
 295         read_output_line (0, 3, 4, 9, '1', "DEBUG", OUTPUT_DELAY,
 296                           MAX_SKIP_DELAY, phase, p,
 297                           &bytes, &delays[3], level)) ||
 298       !(p =
 299         read_output_line (0, 3, 4, 9, 'L', "ERROR", -1,
 300                           1, phase, p,
 301                           &bytes, &delay, level)) ||
 302       !(p =
 303         read_output_line (0, 3, 4, 9, '2', "ERROR", OUTPUT_DELAY,
 304                           MAX_SKIP_DELAY, phase, p,
 305                           &bytes, &delays[4], level)) ||
 306       !(p =
 307         read_output_line (0, 3, 5, 9, 'L', "WARNING", -1,
 308                           1, phase, p,
 309                           &bytes, &delay, level)) ||
 310       !(p =
 311         read_output_line (0, 3, 4, 9, '2', "WARNING", OUTPUT_DELAY,
 312                           MAX_SKIP_DELAY, phase, p,
 313                           &bytes, &delays[5], level)) ||
 314       !(p =
 315         read_output_line (-1, -1, 6, 7, 'L', "INFO", -1,
 316                           1, phase, p,
 317                           &bytes, &delay, level)) ||
 318       !(p =
 319         read_output_line (0, 3, 4, 9, '2', "INFO", OUTPUT_DELAY,
 320                           MAX_SKIP_DELAY, phase, p,
 321                           &bytes, &delays[6], level)) ||
 322       !(p =
 323         read_output_line (-1, -1, 7, 7, 'L', "DEBUG", -1,
 324                           1, phase, p,
 325                           &bytes, &delay, level)) ||
 326       !(p =
 327         read_output_line (0, 3, 4, 9, '2', "DEBUG", OUTPUT_DELAY,
 328                           MAX_SKIP_DELAY, phase, p,
 329                           &bytes, &delays[7], level)))
 330   {
 331     if (bytes == LOG_BUFFER_SIZE)
 332       FPRINTF (stderr, "%s",  "Ran out of buffer space!\n");
 333     GNUNET_break (0);
 334     ok = 2;
 335     GNUNET_SCHEDULER_cancel (die_task);
 336     GNUNET_SCHEDULER_add_now (&end_task, NULL);
 337     return;
 338   }
 339
 340   GNUNET_SCHEDULER_cancel (die_task);
 341   GNUNET_SCHEDULER_add_now (&end_task, NULL);
 342 }
 343
 344
 345 static void
 346 runone ()
 347 {
 348   const struct GNUNET_DISK_FileHandle *stdout_read_handle;
 349
 350   pipe_stdout = GNUNET_DISK_pipe (GNUNET_YES, GNUNET_YES, GNUNET_NO, GNUNET_YES);
 351
 352   if (pipe_stdout == NULL)
 353   {
 354     GNUNET_break (0);
 355     ok = 2;
 356     return;
 357   }
 358
 359   putenv ("GNUNET_LOG=");
 360   putenv ("GNUNET_FORCE_LOG=");
 361   putenv ("GNUNET_FORCE_LOGFILE=");
 362   switch (phase)
 363   {
 364   case 0:
 365     putenv ("GNUNET_LOG=;;;;ERROR");
 366     break;
 367   case 1:
 368     putenv ("GNUNET_LOG=;;;;WARNING");
 369     break;
 370   case 2:
 371     putenv ("GNUNET_LOG=;;;;INFO");
 372     break;
 373   case 3:
 374     putenv ("GNUNET_LOG=;;;;DEBUG");
 375     break;
 376   case 4:
 377     putenv ("GNUNET_FORCE_LOG=;;;;ERROR");
 378     break;
 379   case 5:
 380     putenv ("GNUNET_FORCE_LOG=;;;;WARNING");
 381     break;
 382   case 6:
 383     putenv ("GNUNET_FORCE_LOG=;;;;INFO");
 384     break;
 385   case 7:
 386     putenv ("GNUNET_FORCE_LOG=;;;;DEBUG");
 387     break;
 388   case 8:
 389     putenv ("GNUNET_LOG=blah;;;;ERROR");
 390     break;
 391   case 9:
 392     putenv ("GNUNET_FORCE_LOG=blah;;;;ERROR");
 393     break;
 394   }
 395
 396   proc = GNUNET_OS_start_process (GNUNET_NO, GNUNET_OS_INHERIT_STD_OUT_AND_ERR,
 397                                   NULL, pipe_stdout, NULL,
 398 #if MINGW
 399                                   "test_common_logging_dummy",
 400 #else
 401                                   "./test_common_logging_dummy",
 402 #endif
 403                                   "test_common_logging_dummy", NULL);
 404   GNUNET_assert (NULL != proc);
 405   putenv ("GNUNET_FORCE_LOG=");
 406   putenv ("GNUNET_LOG=");
 407
 408   /* Close the write end of the read pipe */
 409   GNUNET_DISK_pipe_close_end (pipe_stdout, GNUNET_DISK_PIPE_END_WRITE);
 410
 411   stdout_read_handle =
 412       GNUNET_DISK_pipe_handle (pipe_stdout, GNUNET_DISK_PIPE_END_READ);
 413
 414   die_task =
 415       GNUNET_SCHEDULER_add_delayed (GNUNET_TIME_relative_multiply
 416                                     (GNUNET_TIME_UNIT_SECONDS, 10),
 417                                     &end_task,
 418                                     NULL);
 419
 420   bytes = 0;
 421   buf_ptr = buf;
 422   memset (&buf, 0, sizeof (buf));
 423
 424   read_task = GNUNET_SCHEDULER_add_read_file (GNUNET_TIME_UNIT_FOREVER_REL,
 425                                               stdout_read_handle,
 426                                               &read_call,
 427                                               (void*) stdout_read_handle);
 428 }
 429
 430
 431 static void
 432 task (void *cls)
 433 {
 434   phase = 0;
 435   runone ();
 436 }
 437
 438
 439 int
 440 main (int argc, char *argv[])
 441 {
 442   GNUNET_log_setup ("test-common-logging-runtime-loglevels",
 443                     "WARNING",
 444                     NULL);
 445   ok = 1;
 446   GNUNET_SCHEDULER_run (&task, &ok);
 447   return ok;
 448 }
 449
 450 /* end of test_common_logging_runtime_loglevels.c */