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