src/main/log.c

   1 /*
   2  *   This program is free software; you can redistribute it and/or modify
   3  *   it under the terms of the GNU General Public License as published by
   4  *   the Free Software Foundation; either version 2 of the License, or
   5  *   (at your option) any later version.
   6  *
   7  *   This program is distributed in the hope that it will be useful,
   8  *   but WITHOUT ANY WARRANTY; without even the implied warranty of
   9  *   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  10  *   GNU General Public License for more details.
  11  *
  12  *   You should have received a copy of the GNU General Public License
  13  *   along with this program; if not, write to the Free Software
  14  *   Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301, USA
  15  */
  16
  17 /**
  18  * $Id$
  19  *
  20  * @brief Logging functions used by the server core.
  21  * @file main/log.c
  22  *
  23  * @copyright 2000,2006  The FreeRADIUS server project
  24  * @copyright 2000  Miquel van Smoorenburg <miquels@cistron.nl>
  25  * @copyright 2000  Alan DeKok <aland@ox.org>
  26  * @copyright 2001  Chad Miller <cmiller@surfsouth.com>
  27  */
  28 RCSID("$Id$")
  29
  30 #include <freeradius-devel/radiusd.h>
  31 #include <freeradius-devel/rad_assert.h>
  32
  33 #ifdef HAVE_SYS_STAT_H
  34 #  include <sys/stat.h>
  35 #endif
  36
  37 #include <fcntl.h>
  38
  39 #ifdef HAVE_SYSLOG_H
  40 #  include <syslog.h>
  41 #endif
  42
  43 #include <sys/file.h>
  44
  45 #ifdef HAVE_PTHREAD_H
  46 #include <pthread.h>
  47 #endif
  48
  49 log_lvl_t       rad_debug_lvl = 0;              //!< Global debugging level
  50 static bool     rate_limit = true;              //!< Whether repeated log entries should be rate limited
  51
  52 /** Maps log categories to message prefixes
  53  */
  54 static const FR_NAME_NUMBER levels[] = {
  55         { ": Debug: ",          L_DBG           },
  56         { ": Auth: ",           L_AUTH          },
  57         { ": Proxy: ",          L_PROXY         },
  58         { ": Info: ",           L_INFO          },
  59         { ": Warning: ",        L_WARN          },
  60         { ": Acct: ",           L_ACCT          },
  61         { ": Error: ",          L_ERR           },
  62         { ": WARNING: ",        L_DBG_WARN      },
  63         { ": ERROR: ",          L_DBG_ERR       },
  64         { ": WARNING: ",        L_DBG_WARN_REQ  },
  65         { ": ERROR: ",          L_DBG_ERR_REQ   },
  66         { NULL, 0 }
  67 };
  68
  69 /** @name VT100 escape sequences
  70  *
  71  * These sequences may be written to VT100 terminals to change the
  72  * colour and style of the text.
  73  *
  74  @code{.c}
  75    fprintf(stdout, VTC_RED "This text will be coloured red" VTC_RESET);
  76  @endcode
  77  * @{
  78  */
  79 #define VTC_RED         "\x1b[31m"      //!< Colour following text red.
  80 #define VTC_YELLOW      "\x1b[33m"      //!< Colour following text yellow.
  81 #define VTC_BOLD        "\x1b[1m"       //!< Embolden following text.
  82 #define VTC_RESET       "\x1b[0m"       //!< Reset terminal text to default style/colour.
  83 /** @} */
  84
  85 /** Maps log categories to VT100 style/colour escape sequences
  86  */
  87 static const FR_NAME_NUMBER colours[] = {
  88         { "",                   L_DBG           },
  89         { VTC_BOLD,             L_AUTH          },
  90         { VTC_BOLD,             L_PROXY         },
  91         { VTC_BOLD,             L_INFO          },
  92         { VTC_BOLD,             L_ACCT          },
  93         { VTC_RED,              L_ERR           },
  94         { VTC_BOLD VTC_YELLOW,  L_WARN          },
  95         { VTC_BOLD VTC_RED,     L_DBG_ERR       },
  96         { VTC_BOLD VTC_YELLOW,  L_DBG_WARN      },
  97         { VTC_BOLD VTC_RED,     L_DBG_ERR_REQ   },
  98         { VTC_BOLD VTC_YELLOW,  L_DBG_WARN_REQ  },
  99         { NULL, 0 }
 100 };
 101
 102 /** Syslog facility table
 103  *
 104  * Maps syslog facility keywords, to the syslog facility macros defined
 105  * in the system's syslog.h.
 106  *
 107  * @note Not all facilities are supported by every operating system.
 108  *       If a facility is unavailable it will not appear in the table.
 109  */
 110 const FR_NAME_NUMBER syslog_facility_table[] = {
 111 #ifdef LOG_KERN
 112         { "kern",               LOG_KERN        },
 113 #endif
 114 #ifdef LOG_USER
 115         { "user",               LOG_USER        },
 116 #endif
 117 #ifdef LOG_MAIL
 118         { "mail",               LOG_MAIL        },
 119 #endif
 120 #ifdef LOG_DAEMON
 121         { "daemon",             LOG_DAEMON      },
 122 #endif
 123 #ifdef LOG_AUTH
 124         { "auth",               LOG_AUTH        },
 125 #endif
 126 #ifdef LOG_LPR
 127         { "lpr",                LOG_LPR         },
 128 #endif
 129 #ifdef LOG_NEWS
 130         { "news",               LOG_NEWS        },
 131 #endif
 132 #ifdef LOG_UUCP
 133         { "uucp",               LOG_UUCP        },
 134 #endif
 135 #ifdef LOG_CRON
 136         { "cron",               LOG_CRON        },
 137 #endif
 138 #ifdef LOG_AUTHPRIV
 139         { "authpriv",           LOG_AUTHPRIV    },
 140 #endif
 141 #ifdef LOG_FTP
 142         { "ftp",                LOG_FTP         },
 143 #endif
 144 #ifdef LOG_LOCAL0
 145         { "local0",             LOG_LOCAL0      },
 146 #endif
 147 #ifdef LOG_LOCAL1
 148         { "local1",             LOG_LOCAL1      },
 149 #endif
 150 #ifdef LOG_LOCAL2
 151         { "local2",             LOG_LOCAL2      },
 152 #endif
 153 #ifdef LOG_LOCAL3
 154         { "local3",             LOG_LOCAL3      },
 155 #endif
 156 #ifdef LOG_LOCAL4
 157         { "local4",             LOG_LOCAL4      },
 158 #endif
 159 #ifdef LOG_LOCAL5
 160         { "local5",             LOG_LOCAL5      },
 161 #endif
 162 #ifdef LOG_LOCAL6
 163         { "local6",             LOG_LOCAL6      },
 164 #endif
 165 #ifdef LOG_LOCAL7
 166         { "local7",             LOG_LOCAL7      },
 167 #endif
 168         { NULL,                 -1              }
 169 };
 170
 171 /** Syslog severity table
 172  *
 173  * Maps syslog severity keywords, to the syslog severity macros defined
 174  * in the system's syslog.h file.
 175  *
 176  */
 177 const FR_NAME_NUMBER syslog_severity_table[] = {
 178 #ifdef LOG_EMERG
 179         { "emergency",          LOG_EMERG       },
 180 #endif
 181 #ifdef LOG_ALERT
 182         { "alert",              LOG_ALERT       },
 183 #endif
 184 #ifdef LOG_CRIT
 185         { "critical",           LOG_CRIT        },
 186 #endif
 187 #ifdef LOG_ERR
 188         { "error",              LOG_ERR         },
 189 #endif
 190 #ifdef LOG_WARNING
 191         { "warning",            LOG_WARNING     },
 192 #endif
 193 #ifdef LOG_NOTICE
 194         { "notice",             LOG_NOTICE      },
 195 #endif
 196 #ifdef LOG_INFO
 197         { "info",               LOG_INFO        },
 198 #endif
 199 #ifdef LOG_DEBUG
 200         { "debug",              LOG_DEBUG       },
 201 #endif
 202         { NULL,                 -1              }
 203 };
 204
 205 const FR_NAME_NUMBER log_str2dst[] = {
 206         { "null",               L_DST_NULL      },
 207         { "files",              L_DST_FILES     },
 208         { "syslog",             L_DST_SYSLOG    },
 209         { "stdout",             L_DST_STDOUT    },
 210         { "stderr",             L_DST_STDERR    },
 211         { NULL,                 L_DST_NUM_DEST  }
 212 };
 213
 214 bool log_dates_utc = false;
 215
 216 fr_log_t default_log = {
 217         .colourise = false,     //!< Will be set later. Should be off before we do terminal detection.
 218         .fd = STDOUT_FILENO,
 219         .dst = L_DST_STDOUT,
 220         .file = NULL,
 221         .debug_file = NULL,
 222 };
 223
 224 static int stderr_fd = -1;      //!< The original unmolested stderr file descriptor
 225 static int stdout_fd = -1;      //!< The original unmolested stdout file descriptor
 226
 227 static char const spaces[] = "                                                                                                                        ";
 228
 229 /** On fault, reset STDOUT and STDERR to something useful
 230  *
 231  * @return 0
 232  */
 233 static int _restore_std(UNUSED int sig)
 234 {
 235         if ((stderr_fd > 0) && (stdout_fd > 0)) {
 236                 dup2(stderr_fd, STDOUT_FILENO);
 237                 dup2(stdout_fd, STDERR_FILENO);
 238                 return 0;
 239         }
 240
 241         if (default_log.fd > 0) {
 242                 dup2(default_log.fd, STDOUT_FILENO);
 243                 dup2(default_log.fd, STDERR_FILENO);
 244                 return 0;
 245         }
 246
 247         return 0;
 248 }
 249
 250 /** Initialise file descriptors based on logging destination
 251  *
 252  * @param log Logger to manipulate.
 253  * @param daemonize Whether the server is starting as a daemon.
 254  * @return 0 on success -1 on failure.
 255  */
 256 int radlog_init(fr_log_t *log, bool daemonize)
 257 {
 258         int devnull;
 259
 260         rate_limit = daemonize;
 261
 262         /*
 263          *      If we're running in foreground mode, save STDIN /
 264          *      STDERR as higher FDs, which won't get used by anyone
 265          *      else.  When we fork/exec a program, it's STD FDs will
 266          *      get set to pipes.  We later set STDOUT / STDERR to
 267          *      /dev/null, so that any library trying to write to them
 268          *      doesn't screw anything up.
 269          *
 270          *      Then, when something goes wrong, restore them so that
 271          *      any debugger called from the panic action has access
 272          *      to STDOUT / STDERR.
 273          */
 274         if (!daemonize) {
 275                 fr_fault_set_cb(_restore_std);
 276
 277                 stdout_fd = dup(STDOUT_FILENO);
 278                 stderr_fd = dup(STDERR_FILENO);
 279         }
 280
 281         devnull = open("/dev/null", O_RDWR);
 282         if (devnull < 0) {
 283                 fr_strerror_printf("Error opening /dev/null: %s", fr_syserror(errno));
 284                 return -1;
 285         }
 286
 287         /*
 288          *      STDOUT & STDERR go to /dev/null, unless we have "-x",
 289          *      then STDOUT & STDERR go to the "-l log" destination.
 290          *
 291          *      The complexity here is because "-l log" can go to
 292          *      STDOUT or STDERR, too.
 293          */
 294         if (log->dst == L_DST_STDOUT) {
 295                 setlinebuf(stdout);
 296                 log->fd = STDOUT_FILENO;
 297
 298                 /*
 299                  *      If we're debugging, allow STDERR to go to
 300                  *      STDOUT too, for executed programs,
 301                  */
 302                 if (rad_debug_lvl) {
 303                         dup2(STDOUT_FILENO, STDERR_FILENO);
 304                 } else {
 305                         dup2(devnull, STDERR_FILENO);
 306                 }
 307
 308         } else if (log->dst == L_DST_STDERR) {
 309                 setlinebuf(stderr);
 310                 log->fd = STDERR_FILENO;
 311
 312                 /*
 313                  *      If we're debugging, allow STDOUT to go to
 314                  *      STDERR too, for executed programs,
 315                  */
 316                 if (rad_debug_lvl) {
 317                         dup2(STDERR_FILENO, STDOUT_FILENO);
 318                 } else {
 319                         dup2(devnull, STDOUT_FILENO);
 320                 }
 321
 322         } else if (log->dst == L_DST_SYSLOG) {
 323                 /*
 324                  *      Discard STDOUT and STDERR no matter what the
 325                  *      status of debugging.  Syslog isn't a file
 326                  *      descriptor, so we can't use it.
 327                  */
 328                 dup2(devnull, STDOUT_FILENO);
 329                 dup2(devnull, STDERR_FILENO);
 330
 331         } else if (rad_debug_lvl) {
 332                 /*
 333                  *      If we're debugging, allow STDOUT and STDERR to
 334                  *      go to the log file.
 335                  */
 336                 dup2(log->fd, STDOUT_FILENO);
 337                 dup2(log->fd, STDERR_FILENO);
 338
 339         } else {
 340                 /*
 341                  *      Not debugging, and the log isn't STDOUT or
 342                  *      STDERR.  Ensure that we move both of them to
 343                  *      /dev/null, so that the calling terminal can
 344                  *      exit, and the output from executed programs
 345                  *      doesn't pollute STDOUT / STDERR.
 346                  */
 347                 dup2(devnull, STDOUT_FILENO);
 348                 dup2(devnull, STDERR_FILENO);
 349         }
 350
 351         close(devnull);
 352
 353         fr_fault_set_log_fd(log->fd);
 354
 355         return 0;
 356 }
 357
 358 /** Send a server log message to its destination
 359  *
 360  * @param type of log message.
 361  * @param msg with printf style substitution tokens.
 362  * @param ap Substitution arguments.
 363  */
 364 int vradlog(log_type_t type, char const *msg, va_list ap)
 365 {
 366         unsigned char *p;
 367         char buffer[10240];     /* The largest config item size, then extra for prefixes and suffixes */
 368         char *unsan;
 369         size_t len;
 370         int colourise = default_log.colourise;
 371
 372         /*
 373          *      If we don't want any messages, then
 374          *      throw them away.
 375          */
 376         if (default_log.dst == L_DST_NULL) {
 377                 return 0;
 378         }
 379
 380         buffer[0] = '\0';
 381         len = 0;
 382
 383         if (colourise) {
 384                 len += strlcpy(buffer + len, fr_int2str(colours, type, ""), sizeof(buffer) - len) ;
 385                 if (len == 0) {
 386                         colourise = false;
 387                 }
 388         }
 389
 390         /*
 391          *      Mark the point where we treat the buffer as unsanitized.
 392          */
 393         unsan = buffer + len;
 394
 395         /*
 396          *      Don't print timestamps to syslog, it does that for us.
 397          *      Don't print timestamps and error types for low levels
 398          *      of debugging.
 399          *
 400          *      Print timestamps for non-debugging, and for high levels
 401          *      of debugging.
 402          */
 403         if (default_log.dst != L_DST_SYSLOG) {
 404                 if ((rad_debug_lvl != 1) && (rad_debug_lvl != 2)) {
 405                         time_t timeval;
 406
 407                         timeval = time(NULL);
 408                         CTIME_R(&timeval, buffer + len, sizeof(buffer) - len - 1);
 409
 410                         len = strlen(buffer);
 411                         len += strlcpy(buffer + len, fr_int2str(levels, type, ": "), sizeof(buffer) - len);
 412                 } else goto add_prefix;
 413         } else {
 414         add_prefix:
 415                 if (len < sizeof(buffer)) switch (type) {
 416                 case L_DBG_WARN:
 417                         len += strlcpy(buffer + len, "WARNING: ", sizeof(buffer) - len);
 418                         break;
 419
 420                 case L_DBG_ERR:
 421                         len += strlcpy(buffer + len, "ERROR: ", sizeof(buffer) - len);
 422                         break;
 423
 424                 default:
 425                         break;
 426                 }
 427         }
 428
 429         if (len < sizeof(buffer)) {
 430                 len += vsnprintf(buffer + len, sizeof(buffer) - len - 1, msg, ap);
 431         }
 432
 433         /*
 434          *      Filter out control chars and non UTF8 chars
 435          */
 436         for (p = (unsigned char *)unsan; *p != '\0'; p++) {
 437                 int clen;
 438
 439                 switch (*p) {
 440                 case '\r':
 441                 case '\n':
 442                         *p = ' ';
 443                         break;
 444
 445                 case '\t':
 446                         continue;
 447
 448                 default:
 449                         clen = fr_utf8_char(p, -1);
 450                         if (!clen) {
 451                                 *p = '?';
 452                                 continue;
 453                         }
 454                         p += (clen - 1);
 455                         break;
 456                 }
 457         }
 458
 459         if (colourise && (len < sizeof(buffer))) {
 460                 len += strlcpy(buffer + len, VTC_RESET, sizeof(buffer) - len);
 461         }
 462
 463         if (len < (sizeof(buffer) - 2)) {
 464                 buffer[len]     = '\n';
 465                 buffer[len + 1] = '\0';
 466         } else {
 467                 buffer[sizeof(buffer) - 2] = '\n';
 468                 buffer[sizeof(buffer) - 1] = '\0';
 469         }
 470
 471         switch (default_log.dst) {
 472
 473 #ifdef HAVE_SYSLOG_H
 474         case L_DST_SYSLOG:
 475                 switch (type) {
 476                 case L_DBG:
 477                 case L_DBG_WARN:
 478                 case L_DBG_ERR:
 479                 case L_DBG_ERR_REQ:
 480                 case L_DBG_WARN_REQ:
 481                         type = LOG_DEBUG;
 482                         break;
 483
 484                 case L_AUTH:
 485                 case L_PROXY:
 486                 case L_ACCT:
 487                         type = LOG_NOTICE;
 488                         break;
 489
 490                 case L_INFO:
 491                         type = LOG_INFO;
 492                         break;
 493
 494                 case L_WARN:
 495                         type = LOG_WARNING;
 496                         break;
 497
 498                 case L_ERR:
 499                         type = LOG_ERR;
 500                         break;
 501                 }
 502                 syslog(type, "%s", buffer);
 503                 break;
 504 #endif
 505
 506         case L_DST_FILES:
 507         case L_DST_STDOUT:
 508         case L_DST_STDERR:
 509                 return write(default_log.fd, buffer, strlen(buffer));
 510
 511         default:
 512         case L_DST_NULL:        /* should have been caught above */
 513                 break;
 514         }
 515
 516         return 0;
 517 }
 518
 519 /** Send a server log message to its destination
 520  *
 521  * @param type of log message.
 522  * @param msg with printf style substitution tokens.
 523  * @param ... Substitution arguments.
 524  */
 525 int radlog(log_type_t type, char const *msg, ...)
 526 {
 527         va_list ap;
 528         int r = 0;
 529
 530         va_start(ap, msg);
 531
 532         /*
 533          *      Non-debug message, or debugging is enabled.  Log it.
 534          */
 535         if (((type & L_DBG) == 0) || (rad_debug_lvl > 0)) {
 536                 r = vradlog(type, msg, ap);
 537         }
 538         va_end(ap);
 539
 540         return r;
 541 }
 542
 543 /** Send a server log message to its destination without evaluating its debug level
 544  *
 545  * @param type of log message.
 546  * @param msg with printf style substitution tokens.
 547  * @param ... Substitution arguments.
 548  */
 549 static int radlog_always(log_type_t type, char const *msg, ...) CC_HINT(format (printf, 2, 3));
 550 static int radlog_always(log_type_t type, char const *msg, ...)
 551 {
 552         va_list ap;
 553         int r;
 554
 555         va_start(ap, msg);
 556         r = vradlog(type, msg, ap);
 557         va_end(ap);
 558
 559         return r;
 560 }
 561
 562 /** Whether a server debug message should be logged
 563  *
 564  * @param type of message.
 565  * @param lvl of debugging this message should be logged at.
 566  * @return true if message should be logged, else false.
 567  */
 568 inline bool debug_enabled(log_type_t type, log_lvl_t lvl)
 569 {
 570         if ((type & L_DBG) && (lvl <= rad_debug_lvl)) return true;
 571
 572         return false;
 573 }
 574
 575 /** Whether rate limiting is enabled
 576  */
 577 bool rate_limit_enabled(void)
 578 {
 579         if (rate_limit || (rad_debug_lvl < 1)) return true;
 580
 581         return false;
 582 }
 583
 584 /** Whether a request specific debug message should be logged
 585  *
 586  * @param type of message.
 587  * @param lvl of debugging this message should be logged at.
 588  * @param request The current request.
 589  * @return true if message should be logged, else false.
 590  */
 591 inline bool radlog_debug_enabled(log_type_t type, log_lvl_t lvl, REQUEST *request)
 592 {
 593         /*
 594          *      It's a debug class message, note this doesn't mean it's a debug type message.
 595          *
 596          *      For example it could be a RIDEBUG message, which would be an informational message,
 597          *      instead of an RDEBUG message which would be a debug debug message.
 598          *
 599          *      There is log function, but the request debug level isn't high enough.
 600          *      OR, we're in debug mode, and the global debug level isn't high enough,
 601          *      then don't log the message.
 602          */
 603         if ((type & L_DBG) &&
 604             ((request && request->log.func && (lvl <= request->log.lvl)) ||
 605              ((rad_debug_lvl != 0) && (lvl <= rad_debug_lvl)))) {
 606                 return true;
 607         }
 608
 609         return false;
 610 }
 611
 612 /** Send a log message to its destination, possibly including fields from the request
 613  *
 614  * @param type of log message, #L_ERR, #L_WARN, #L_INFO, #L_DBG.
 615  * @param lvl Minimum required server or request level to output this message.
 616  * @param request The current request.
 617  * @param msg with printf style substitution tokens.
 618  * @param ap Substitution arguments.
 619  */
 620 void vradlog_request(log_type_t type, log_lvl_t lvl, REQUEST *request, char const *msg, va_list ap)
 621 {
 622         size_t len = 0;
 623         char const *filename = default_log.file;
 624         FILE *fp = NULL;
 625
 626         char buffer[10240];     /* The largest config item size, then extra for prefixes and suffixes */
 627
 628         char *p;
 629         char const *extra = "";
 630         uint8_t indent;
 631         va_list aq;
 632
 633         rad_assert(request);
 634
 635         /*
 636          *      Debug messages get treated specially.
 637          */
 638         if ((type & L_DBG) != 0) {
 639
 640                 if (!radlog_debug_enabled(type, lvl, request)) {
 641                         return;
 642                 }
 643
 644                 /*
 645                  *      Use the debug output file, if specified,
 646                  *      otherwise leave it as the default log file.
 647                  */
 648 #ifdef WITH_COMMAND_SOCKET
 649                 filename = default_log.debug_file;
 650                 if (!filename)
 651 #endif
 652                 {
 653                         filename = default_log.file;
 654                 }
 655         }
 656
 657         if (filename) {
 658                 radlog_func_t rl = request->log.func;
 659
 660                 request->log.func = NULL;
 661
 662                 /*
 663                  *      This is SLOW!  Doing it for every log message
 664                  *      in every request is NOT recommended!
 665                  */
 666                 if (radius_xlat(buffer, sizeof(buffer), request, filename, rad_filename_escape, NULL) < 0) return;
 667                 request->log.func = rl;
 668
 669                 /*
 670                  *      Ensure the directory structure exists, for
 671                  *      where we're going to write the log file.
 672                  */
 673                 p = strrchr(buffer, FR_DIR_SEP);
 674                 if (p) {
 675                         *p = '\0';
 676                         if (rad_mkdir(buffer, S_IRWXU, -1, -1) < 0) {
 677                                 ERROR("Failed creating %s: %s", buffer, fr_syserror(errno));
 678                                 return;
 679                         }
 680                         *p = FR_DIR_SEP;
 681                 }
 682
 683                 fp = fopen(buffer, "a");
 684         }
 685
 686         /*
 687          *  If we don't copy the original ap we get a segfault from vasprintf. This is apparently
 688          *  due to ap sometimes being implemented with a stack offset which is invalidated if
 689          *  ap is passed into another function. See here:
 690          *  http://julipedia.meroh.net/2011/09/using-vacopy-to-safely-pass-ap.html
 691          *
 692          *  I don't buy that explanation, but doing a va_copy here does prevent SEGVs seen when
 693          *  running unit tests which generate errors under CI.
 694          */
 695         va_copy(aq, ap);
 696         vsnprintf(buffer + len, sizeof(buffer) - len, msg, aq);
 697         va_end(aq);
 698
 699         /*
 700          *      Make sure the indent isn't set to something crazy
 701          */
 702         indent = request->log.indent > sizeof(spaces) ?
 703                  sizeof(spaces) :
 704                  request->log.indent;
 705
 706         /*
 707          *      Logging to a file descriptor
 708          */
 709         if (fp) {
 710                 char time_buff[64];     /* The current timestamp */
 711
 712                 time_t timeval;
 713                 timeval = time(NULL);
 714
 715 #ifdef HAVE_GMTIME_R
 716                 if (log_dates_utc) {
 717                         struct tm utc;
 718                         gmtime_r(&timeval, &utc);
 719                         ASCTIME_R(&utc, time_buff, sizeof(time_buff));
 720                 } else
 721 #endif
 722                 {
 723                         CTIME_R(&timeval, time_buff, sizeof(time_buff));
 724                 }
 725
 726                 /*
 727                  *      Strip trailing new lines
 728                  */
 729                 p = strrchr(time_buff, '\n');
 730                 if (p) p[0] = '\0';
 731
 732                 if (request->module && (request->module[0] != '\0')) {
 733                         fprintf(fp, "(%u) %s%s%s: %.*s%s\n",
 734                                 request->number, time_buff, fr_int2str(levels, type, ""),
 735                                 request->module, indent, spaces, buffer);
 736                 } else {
 737                         fprintf(fp, "(%u) %s%s%.*s%s\n",
 738                                 request->number, time_buff, fr_int2str(levels, type, ""),
 739                                 indent, spaces, buffer);
 740                 }
 741                 fclose(fp);
 742                 return;
 743         }
 744
 745         /*
 746          *      Logging everywhere else
 747          */
 748         if (!DEBUG_ENABLED3) switch (type) {
 749         case L_DBG_WARN:
 750                 extra = "WARNING: ";
 751                 type = L_DBG_WARN_REQ;
 752                 break;
 753
 754         case L_DBG_ERR:
 755                 extra = "ERROR: ";
 756                 type = L_DBG_ERR_REQ;
 757                 break;
 758         default:
 759                 break;
 760         }
 761
 762         if (request->module && (request->module[0] != '\0')) {
 763                 radlog_always(type, "(%u) %s: %.*s%s%s", request->number,
 764                               request->module, indent, spaces, extra, buffer);
 765         } else {
 766                 radlog_always(type, "(%u) %.*s%s%s", request->number,
 767                               indent, spaces, extra, buffer);
 768         }
 769 }
 770
 771 /** Martial variadic log arguments into a va_list and pass to normal logging functions
 772  *
 773  * @see radlog_request_error for more details.
 774  *
 775  * @param type the log category.
 776  * @param lvl of debugging this message should be logged at.
 777  * @param request The current request.
 778  * @param msg with printf style substitution tokens.
 779  * @param ... Substitution arguments.
 780  */
 781 void radlog_request(log_type_t type, log_lvl_t lvl, REQUEST *request, char const *msg, ...)
 782 {
 783         va_list ap;
 784
 785         rad_assert(request);
 786
 787         if (!request->log.func && !(type & L_DBG)) return;
 788
 789         va_start(ap, msg);
 790         if (request->log.func) request->log.func(type, lvl, request, msg, ap);
 791         else if (!(type & L_DBG)) vradlog_request(type, lvl, request, msg, ap);
 792         va_end(ap);
 793 }
 794
 795 /** Martial variadic log arguments into a va_list and pass to error logging functions
 796  *
 797  * This could all be done in a macro, but it turns out some implementations of the
 798  * variadic macros do not work at all well if the va_list being written to is further
 799  * up the stack (which is required as you still need a function to convert the elipses
 800  * into a va_list).
 801  *
 802  * So, we use this small wrapper function instead, which will hopefully guarantee
 803  * consistent behaviour.
 804  *
 805  * @param type the log category.
 806  * @param lvl of debugging this message should be logged at.
 807  * @param request The current request.
 808  * @param msg with printf style substitution tokens.
 809  * @param ... Substitution arguments.
 810  */
 811 void radlog_request_error(log_type_t type, log_lvl_t lvl, REQUEST *request, char const *msg, ...)
 812 {
 813         va_list ap;
 814
 815         rad_assert(request);
 816
 817         va_start(ap, msg);
 818         if (request->log.func) request->log.func(type, lvl, request, msg, ap);
 819         else if (!(type & L_DBG)) vradlog_request(type, lvl, request, msg, ap);
 820         vmodule_failure_msg(request, msg, ap);
 821         va_end(ap);
 822 }
 823
 824 /** Write the string being parsed, and a marker showing where the parse error occurred
 825  *
 826  * @param type the log category.
 827  * @param lvl of debugging this message should be logged at.
 828  * @param request The current request.
 829  * @param msg string we were parsing.
 830  * @param idx The position of the marker relative to the string.
 831  * @param error What the parse error was.
 832  */
 833 void radlog_request_marker(log_type_t type, log_lvl_t lvl, REQUEST *request,
 834                            char const *msg, size_t idx, char const *error)
 835 {
 836         char const *prefix = "";
 837         uint8_t indent;
 838
 839         rad_assert(request);
 840
 841         if (idx >= sizeof(spaces)) {
 842                 size_t offset = (idx - (sizeof(spaces) - 1)) + (sizeof(spaces) * 0.75);
 843                 idx -= offset;
 844                 msg += offset;
 845
 846                 prefix = "... ";
 847         }
 848
 849         /*
 850          *  Don't want format markers being indented
 851          */
 852         indent = request->log.indent;
 853         request->log.indent = 0;
 854
 855         radlog_request(type, lvl, request, "%s%s", prefix, msg);
 856         radlog_request(type, lvl, request, "%s%.*s^ %s", prefix, (int) idx, spaces, error);
 857
 858         request->log.indent = indent;
 859 }
 860
 861
 862 /** Canonicalize error strings, removing tabs, and generate spaces for error marker
 863  *
 864  * @note talloc_free must be called on the buffer returned in spaces and text
 865  *
 866  * Used to produce error messages such as this:
 867  @verbatim
 868   I'm a string with a parser # error
 869                              ^ Unexpected character in string
 870  @endverbatim
 871  *
 872  * With code resembling this:
 873  @code{.c}
 874    ERROR("%s", parsed_str);
 875    ERROR("%s^ %s", space, text);
 876  @endcode
 877  *
 878  * @todo merge with above function (radlog_request_marker)
 879  *
 880  * @param sp Where to write a dynamically allocated buffer of spaces used to indent the error text.
 881  * @param text Where to write the canonicalized version of msg (the error text).
 882  * @param ctx to allocate the spaces and text buffers in.
 883  * @param slen of error marker. Expects negative integer value, as returned by parse functions.
 884  * @param msg to canonicalize.
 885  */
 886 void fr_canonicalize_error(TALLOC_CTX *ctx, char **sp, char **text, ssize_t slen, char const *msg)
 887 {
 888         size_t offset, skip = 0;
 889         char *spbuf, *p;
 890         char *value;
 891
 892         offset = -slen;
 893
 894         /*
 895          *      Ensure that the error isn't indented
 896          *      too far.
 897          */
 898         if (offset > 45) {
 899                 skip = offset - 40;
 900                 offset -= skip;
 901                 value = talloc_strdup(ctx, msg + skip);
 902                 memcpy(value, "...", 3);
 903
 904         } else {
 905                 value = talloc_strdup(ctx, msg);
 906         }
 907
 908         spbuf = talloc_array(ctx, char, offset + 1);
 909         memset(spbuf, ' ', offset);
 910         spbuf[offset] = '\0';
 911
 912         /*
 913          *      Smash tabs to spaces for the input string.
 914          */
 915         for (p = value; *p != '\0'; p++) {
 916                 if (*p == '\t') *p = ' ';
 917         }
 918
 919
 920         /*
 921          *      Ensure that there isn't too much text after the error.
 922          */
 923         if (strlen(value) > 100) {
 924                 memcpy(value + 95, "... ", 5);
 925         }
 926
 927         *sp = spbuf;
 928         *text = value;
 929 }
 930