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      SPDX-License-Identifier: AGPL3.0-or-later
  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 ( \
  36     GNUNET_TIME_UNIT_MICROSECONDS, 400).rel_value_us
  37
  38 /**
  39  * How much time non-skipped log call should take, at least.
  40  * Keep in sync with the value in the dummy!
  41  */
  42 #define OUTPUT_DELAY GNUNET_TIME_relative_multiply ( \
  43     GNUNET_TIME_UNIT_MICROSECONDS, 1000).rel_value_us
  44
  45 static int ok;
  46
  47 static int phase = 0;
  48
  49 static struct GNUNET_OS_Process *proc;
  50
  51 /* Pipe to read from started processes stdout (on read end) */
  52 static struct GNUNET_DISK_PipeHandle *pipe_stdout;
  53
  54 static struct GNUNET_SCHEDULER_Task *die_task;
  55
  56 static struct GNUNET_SCHEDULER_Task *read_task;
  57
  58 static void
  59 runone (void);
  60
  61
  62 static void
  63 end_task (void *cls)
  64 {
  65   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Ending phase %d, ok is %d\n", phase,
  66               ok);
  67   if (NULL != proc)
  68   {
  69     if (0 != GNUNET_OS_process_kill (proc, GNUNET_TERM_SIG))
  70     {
  71       GNUNET_log_strerror (GNUNET_ERROR_TYPE_WARNING, "kill");
  72     }
  73     GNUNET_OS_process_wait (proc);
  74     GNUNET_OS_process_destroy (proc);
  75     proc = NULL;
  76   }
  77   if (NULL != read_task)
  78   {
  79     GNUNET_SCHEDULER_cancel (read_task);
  80     read_task = NULL;
  81   }
  82   GNUNET_DISK_pipe_close (pipe_stdout);
  83   if (ok == 1)
  84   {
  85     if (phase < 9)
  86     {
  87       phase += 1;
  88       runone ();
  89     }
  90     else
  91       ok = 0;
  92   }
  93   else
  94     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "failing\n");
  95 }
  96
  97
  98 static char *
  99 read_output_line (int phase_from1, int phase_to1, int phase_from2,
 100                   int phase_to2, char c, const char *expect_level,
 101                   long delay_morethan, long delay_lessthan, int phase,
 102                   char *p,
 103                   int *len, long *delay, char level[8])
 104 {
 105   char *r = p;
 106   char t[7];
 107   int i, j, stop = 0;
 108   int level_matches;
 109   int delay_is_sane;
 110   int delay_is_a_dummy;
 111   int delay_outside_of_range;
 112
 113   j = 0;
 114   int stage = 0;
 115
 116   if (! ((phase >= phase_from1) && (phase <= phase_to1)) &&
 117       ! ((phase >= phase_from2) && (phase <= phase_to2)))
 118     return p;
 119 #if 0
 120   GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
 121               "Trying to match '%c%s \\d\\r\\n' on %s\n", c, expect_level, p);
 122 #endif
 123   for (i = 0; i < *len && ! stop; i++)
 124   {
 125     switch (stage)
 126     {
 127     case 0:                    /* read first char */
 128       if (r[i] != c)
 129       {
 130         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Expected '%c', but got '%c'\n", c,
 131                     r[i]);
 132         GNUNET_break (0);
 133         return NULL;
 134       }
 135       stage += 1;
 136       break;
 137
 138     case 1:                    /* read at most 7 char-long error level string, finished by ' ' */
 139       if (r[i] == ' ')
 140       {
 141         level[j] = '\0';
 142         stage += 1;
 143         j = 0;
 144       }
 145       else if (i == 8)
 146       {
 147         GNUNET_break (0);
 148         ok = 2;
 149         return NULL;
 150       }
 151       else
 152         level[j++] = r[i];
 153       break;
 154
 155     case 2:                    /* read the delay, finished by '\n' */
 156       t[j++] = r[i];
 157       if (r[i] == '\n')
 158       {
 159         t[j - 1] = '\0';
 160         *delay = strtol (t, NULL, 10);
 161         stop = 1;
 162       }
 163       break;
 164     }
 165   }
 166   level_matches = (strcmp (expect_level, level) == 0);
 167   delay_is_sane = (*delay >= 0) && (*delay <= 1000000);
 168   delay_is_a_dummy = (c == 'L');
 169   /* Delay must be either less than 'lessthan' (log call is skipped)
 170    * or more than 'morethan' (log call is not skipped)
 171    */
 172   delay_outside_of_range = ((*delay < delay_lessthan) || (*delay >=
 173                                                           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 /**
 201  * Up to 8 non-skipped GNUNET_log() calls
 202  * + extra line with delay for each one
 203  */
 204 #define LOG_MAX_NUM_LINES (8 * 2)
 205 /**
 206  * Actual message is 17 chars at most
 207  */
 208 #define LOG_MAX_LINE_LENGTH (17)
 209
 210 #define LOG_BUFFER_SIZE LOG_MAX_NUM_LINES *LOG_MAX_LINE_LENGTH
 211
 212 static char buf[LOG_BUFFER_SIZE];
 213
 214 static char *buf_ptr;
 215
 216 static int bytes;
 217
 218
 219 static void
 220 read_call (void *cls)
 221 {
 222   const struct GNUNET_DISK_FileHandle *stdout_read_handle = cls;
 223   char level[8];
 224   long delay;
 225   long delays[8];
 226   int rd;
 227
 228   read_task = NULL;
 229   rd = GNUNET_DISK_file_read (stdout_read_handle, buf_ptr,
 230                               sizeof(buf) - bytes);
 231   if (rd > 0)
 232   {
 233     buf_ptr += rd;
 234     bytes += rd;
 235 #if VERBOSE
 236     fprintf (stderr, "got %d bytes, reading more\n", rd);
 237 #endif
 238     read_task = GNUNET_SCHEDULER_add_read_file (GNUNET_TIME_UNIT_FOREVER_REL,
 239                                                 stdout_read_handle,
 240                                                 &read_call,
 241                                                 (void*) stdout_read_handle);
 242     return;
 243   }
 244
 245 #if VERBOSE
 246   fprintf (stderr, "bytes is %d:%s\n", bytes, buf);
 247 #endif
 248
 249   /* +------CHILD OUTPUT--
 250    * |      SOFT     HARD
 251    * |    E W I D  E W I D
 252    * | 0E *        * *
 253    * | 1W * *      * *
 254    * P 2I * * *    * *
 255    * H 3D * * * *  * *
 256    * A
 257    * S 4E *        *
 258    * E 5W * *      * *
 259    * | 6I * * *    * * *
 260    * | 7D * * * *  * * * *
 261    * | 8  * *      * *
 262    * | 9  * *      * *
 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,
 351                                   GNUNET_YES);
 352
 353   if (pipe_stdout == NULL)
 354   {
 355     GNUNET_break (0);
 356     ok = 2;
 357     return;
 358   }
 359
 360   putenv ("GNUNET_LOG=");
 361   putenv ("GNUNET_FORCE_LOG=");
 362   putenv ("GNUNET_FORCE_LOGFILE=");
 363   switch (phase)
 364   {
 365   case 0:
 366     putenv ("GNUNET_LOG=;;;;ERROR");
 367     break;
 368
 369   case 1:
 370     putenv ("GNUNET_LOG=;;;;WARNING");
 371     break;
 372
 373   case 2:
 374     putenv ("GNUNET_LOG=;;;;INFO");
 375     break;
 376
 377   case 3:
 378     putenv ("GNUNET_LOG=;;;;DEBUG");
 379     break;
 380
 381   case 4:
 382     putenv ("GNUNET_FORCE_LOG=;;;;ERROR");
 383     break;
 384
 385   case 5:
 386     putenv ("GNUNET_FORCE_LOG=;;;;WARNING");
 387     break;
 388
 389   case 6:
 390     putenv ("GNUNET_FORCE_LOG=;;;;INFO");
 391     break;
 392
 393   case 7:
 394     putenv ("GNUNET_FORCE_LOG=;;;;DEBUG");
 395     break;
 396
 397   case 8:
 398     putenv ("GNUNET_LOG=blah;;;;ERROR");
 399     break;
 400
 401   case 9:
 402     putenv ("GNUNET_FORCE_LOG=blah;;;;ERROR");
 403     break;
 404   }
 405
 406   proc = GNUNET_OS_start_process (GNUNET_NO, GNUNET_OS_INHERIT_STD_OUT_AND_ERR,
 407                                   NULL, pipe_stdout, NULL,
 408                                   "./test_common_logging_dummy",
 409                                   "test_common_logging_dummy", NULL);
 410   GNUNET_assert (NULL != proc);
 411   putenv ("GNUNET_FORCE_LOG=");
 412   putenv ("GNUNET_LOG=");
 413
 414   /* Close the write end of the read pipe */
 415   GNUNET_DISK_pipe_close_end (pipe_stdout, GNUNET_DISK_PIPE_END_WRITE);
 416
 417   stdout_read_handle =
 418     GNUNET_DISK_pipe_handle (pipe_stdout, GNUNET_DISK_PIPE_END_READ);
 419
 420   die_task =
 421     GNUNET_SCHEDULER_add_delayed (GNUNET_TIME_relative_multiply
 422                                     (GNUNET_TIME_UNIT_SECONDS, 10),
 423                                   &end_task,
 424                                   NULL);
 425
 426   bytes = 0;
 427   buf_ptr = buf;
 428   memset (&buf, 0, sizeof(buf));
 429
 430   read_task = GNUNET_SCHEDULER_add_read_file (GNUNET_TIME_UNIT_FOREVER_REL,
 431                                               stdout_read_handle,
 432                                               &read_call,
 433                                               (void*) stdout_read_handle);
 434 }
 435
 436
 437 static void
 438 task (void *cls)
 439 {
 440   phase = 0;
 441   runone ();
 442 }
 443
 444
 445 int
 446 main (int argc, char *argv[])
 447 {
 448   GNUNET_log_setup ("test-common-logging-runtime-loglevels",
 449                     "WARNING",
 450                     NULL);
 451   ok = 1;
 452   GNUNET_SCHEDULER_run (&task, &ok);
 453   return ok;
 454 }
 455
 456
 457 /* end of test_common_logging_runtime_loglevels.c */