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