src/util/test_common_logging_runtime_loglevels.c

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