git.tinc-vpn.org Git - tinc/blob - src/logger.c

   1 /*
   2     logger.c -- logging code
   3     Copyright (C) 2004-2022 Guus Sliepen <guus@tinc-vpn.org>
   4                   2004-2005 Ivo Timmermans
   5
   6     This program is free software; you can redistribute it and/or modify
   7     it under the terms of the GNU General Public License as published by
   8     the Free Software Foundation; either version 2 of the License, or
   9     (at your option) any later version.
  10
  11     This program is distributed in the hope that it will be useful,
  12     but WITHOUT ANY WARRANTY; without even the implied warranty of
  13     MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14     GNU General Public License for more details.
  15
  16     You should have received a copy of the GNU General Public License along
  17     with this program; if not, write to the Free Software Foundation, Inc.,
  18     51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
  19 */
  20
  21 #include "system.h"
  22
  23 #include "conf.h"
  24 #include "meta.h"
  25 #include "names.h"
  26 #include "logger.h"
  27 #include "connection.h"
  28 #include "control_common.h"
  29 #include "process.h"
  30 #include "sptps.h"
  31 #include "console.h"
  32
  33 debug_t debug_level = DEBUG_NOTHING;
  34 static logmode_t logmode = LOGMODE_STDERR;
  35 static pid_t logpid;
  36 static FILE *logfile = NULL;
  37 #ifdef HAVE_WINDOWS
  38 static HANDLE loghandle = NULL;
  39 #endif
  40 static const char *logident = NULL;
  41 static bool colorize_stderr = false;
  42 bool logcontrol = false; // controlled by REQ_LOG <level>
  43 int umbilical = 0;
  44 bool umbilical_colorize = false;
  45
  46 #define SGR(s) ("\x1b[" s "m")
  47
  48 typedef enum color_t {
  49         RED, GREEN, YELLOW, BLUE, MAGENTA, CYAN, WHITE, GRAY,
  50         RESET, // not really a color
  51 } color_t;
  52
  53 typedef struct priority_disp_t {
  54         const char *name;
  55         color_t color;
  56 } priority_disp_t;
  57
  58 static const priority_disp_t priorities[] = {
  59         [LOG_EMERG]   = {"EMERGENCY", MAGENTA},
  60         [LOG_ALERT]   = {"ALERT",     MAGENTA},
  61         [LOG_CRIT]    = {"CRITICAL",  MAGENTA},
  62         [LOG_ERR]     = {"ERROR",     RED},
  63         [LOG_WARNING] = {"WARNING",   YELLOW},
  64         [LOG_NOTICE]  = {"NOTICE",    CYAN},
  65         [LOG_INFO]    = {"INFO",      GREEN},
  66         [LOG_DEBUG]   = {"DEBUG",     BLUE},
  67 };
  68
  69 static const char *ansi_codes[] = {
  70         [RED]     = SGR("31;1"),
  71         [GREEN]   = SGR("32;1"),
  72         [YELLOW]  = SGR("33;1"),
  73         [BLUE]    = SGR("34;1"),
  74         [MAGENTA] = SGR("35;1"),
  75         [CYAN]    = SGR("36;1"),
  76         [WHITE]   = SGR("37;1"),
  77         [GRAY]    = SGR("90"),
  78         [RESET]   = SGR("0"),
  79 };
  80
  81 static priority_disp_t get_priority(int priority) {
  82         static const priority_disp_t unknown = {"UNKNOWN", WHITE};
  83
  84         if(priority >= LOG_EMERG && priority <= LOG_DEBUG) {
  85                 return priorities[priority];
  86         } else {
  87                 return unknown;
  88         }
  89 }
  90
  91 // Formats current time to the second.
  92 // Reuses result so repeated calls within the same second are more efficient.
  93 static const char *current_time_str(void) {
  94         static char timestr[sizeof("2000-12-31 12:34:56")] = "";
  95         static time_t last_time = 0;
  96
  97         if(!now.tv_sec) {
  98                 gettimeofday(&now, NULL);
  99         }
 100
 101         time_t now_sec = now.tv_sec;
 102
 103         if(!*timestr || now_sec != last_time) {
 104                 last_time = now_sec;
 105                 strftime(timestr, sizeof(timestr), "%Y-%m-%d %H:%M:%S", localtime(&now_sec));
 106         }
 107
 108         return timestr;
 109 }
 110
 111 // Format log entry with time, log level, and (possibly) colors, remembering if it was colorized.
 112 // Returns true if buffer has been changed.
 113 static bool format_pretty(char *buf, size_t buflen, int prio, const char *message, bool colorize, bool *colorized) {
 114         // If we already wrote to buffer, and its colorization matches, we're done here
 115         if(*buf && colorize == *colorized) {
 116                 return false;
 117         }
 118
 119         // Otherwise, remember current colorization for future comparisons
 120         *colorized = colorize;
 121
 122         priority_disp_t priority = get_priority(prio);
 123         const char *color = "", *reset = "", *timecol = "";
 124
 125         if(colorize) {
 126                 color = ansi_codes[priority.color];
 127                 reset = ansi_codes[RESET];
 128                 timecol = ansi_codes[GRAY];
 129         }
 130
 131         const char *timestr = current_time_str();
 132         snprintf(buf, buflen, "%s%s %s%-7s%s %s", timecol, timestr, color, priority.name, reset, message);
 133         return true;
 134 }
 135
 136 static bool should_log(debug_t level) {
 137         return (level <= debug_level && logmode != LOGMODE_NULL) || logcontrol;
 138 }
 139
 140 static void real_logger(debug_t level, int priority, const char *message) {
 141         char pretty[1024] = "";
 142         bool pretty_colorized = false;
 143         static bool suppress = false;
 144
 145         if(suppress) {
 146                 return;
 147         }
 148
 149         if(level <= debug_level) {
 150                 switch(logmode) {
 151                 case LOGMODE_STDERR:
 152                         format_pretty(pretty, sizeof(pretty), priority, message, colorize_stderr, &pretty_colorized);
 153                         fprintf(stderr, "%s\n", pretty);
 154                         fflush(stderr);
 155                         break;
 156
 157                 case LOGMODE_FILE: {
 158                         const char *timestr = current_time_str();
 159                         fprintf(logfile, "%s %s[%ld]: %s\n", timestr, logident, (long)logpid, message);
 160                         fflush(logfile);
 161                         break;
 162                 }
 163
 164                 case LOGMODE_SYSLOG:
 165 #ifdef HAVE_WINDOWS
 166                         {
 167                                 const char *messages[] = {message};
 168                                 ReportEvent(loghandle, priority, 0, 0, NULL, 1, 0, messages, NULL);
 169                         }
 170
 171 #else
 172 #ifdef HAVE_SYSLOG_H
 173                         syslog(priority, "%s", message);
 174 #endif
 175 #endif
 176                         break;
 177
 178                 case LOGMODE_NULL:
 179                 default:
 180                         break;
 181                 }
 182
 183                 if(umbilical && do_detach) {
 184                         format_pretty(pretty, sizeof(pretty), priority, message, umbilical_colorize, &pretty_colorized);
 185
 186                         if(write(umbilical, pretty, strlen(pretty)) == -1 || write(umbilical, "\n", 1) == -1) {
 187                                 // Other end broken, nothing we can do about it.
 188                         }
 189                 }
 190         }
 191
 192         if(logcontrol) {
 193                 suppress = true;
 194                 logcontrol = false;
 195
 196                 size_t msglen = strlen(pretty);
 197
 198                 for list_each(connection_t, c, &connection_list) {
 199                         if(!c->status.log) {
 200                                 continue;
 201                         }
 202
 203                         logcontrol = true;
 204
 205                         if(level > (c->log_level != DEBUG_UNSET ? c->log_level : debug_level)) {
 206                                 continue;
 207                         }
 208
 209                         if(format_pretty(pretty, sizeof(pretty), priority, message, c->status.log_color, &pretty_colorized)) {
 210                                 msglen = strlen(pretty);
 211                         }
 212
 213                         if(send_request(c, "%d %d %lu", CONTROL, REQ_LOG, (unsigned long)msglen)) {
 214                                 send_meta(c, pretty, msglen);
 215                         }
 216                 }
 217
 218                 suppress = false;
 219         }
 220 }
 221
 222 void logger(debug_t level, int priority, const char *format, ...) {
 223         va_list ap;
 224         char message[1024] = "";
 225
 226         if(!should_log(level)) {
 227                 return;
 228         }
 229
 230         va_start(ap, format);
 231         int len = vsnprintf(message, sizeof(message), format, ap);
 232         message[sizeof(message) - 1] = 0;
 233         va_end(ap);
 234
 235         if(len > 0 && (size_t)len < sizeof(message) - 1 && message[len - 1] == '\n') {
 236                 message[len - 1] = 0;
 237         }
 238
 239         real_logger(level, priority, message);
 240 }
 241
 242 static void sptps_logger(sptps_t *s, int s_errno, const char *format, va_list ap) ATTR_FORMAT(printf, 3, 0);
 243 static void sptps_logger(sptps_t *s, int s_errno, const char *format, va_list ap) {
 244         (void)s_errno;
 245         char message[1024];
 246         size_t msglen = sizeof(message);
 247
 248         if(!should_log(DEBUG_TRAFFIC)) {
 249                 return;
 250         }
 251
 252         int len = vsnprintf(message, msglen, format, ap);
 253         message[sizeof(message) - 1] = 0;
 254
 255         if(len > 0 && (size_t)len < sizeof(message) - 1) {
 256                 if(message[len - 1] == '\n') {
 257                         message[--len] = 0;
 258                 }
 259
 260                 // WARNING: s->handle can point to a connection_t or a node_t,
 261                 // but both types have the name and hostname fields at the same offsets.
 262                 connection_t *c = s->handle;
 263
 264                 if(c) {
 265                         snprintf(message + len, sizeof(message) - len, " from %s (%s)", c->name, c->hostname);
 266                 }
 267         }
 268
 269         real_logger(DEBUG_TRAFFIC, LOG_ERR, message);
 270 }
 271
 272 void openlogger(const char *ident, logmode_t mode) {
 273         logident = ident;
 274         logmode = mode;
 275
 276         switch(mode) {
 277         case LOGMODE_STDERR:
 278                 logpid = getpid();
 279                 colorize_stderr = use_ansi_escapes(stderr);
 280                 break;
 281
 282         case LOGMODE_FILE:
 283                 logpid = getpid();
 284                 logfile = fopen(logfilename, "a");
 285
 286                 if(!logfile) {
 287                         fprintf(stderr, "Could not open log file %s: %s\n", logfilename, strerror(errno));
 288                         logmode = LOGMODE_NULL;
 289                 }
 290
 291                 break;
 292
 293         case LOGMODE_SYSLOG:
 294 #ifdef HAVE_WINDOWS
 295                 loghandle = RegisterEventSource(NULL, logident);
 296
 297                 if(!loghandle) {
 298                         fprintf(stderr, "Could not open log handle!\n");
 299                         logmode = LOGMODE_NULL;
 300                 }
 301
 302                 break;
 303 #else
 304 #ifdef HAVE_SYSLOG_H
 305                 openlog(logident, LOG_CONS | LOG_PID, LOG_DAEMON);
 306                 break;
 307 #endif
 308 #endif
 309
 310         case LOGMODE_NULL:
 311         default:
 312                 break;
 313         }
 314
 315         if(logmode != LOGMODE_NULL) {
 316                 sptps_log = sptps_logger;
 317         } else {
 318                 sptps_log = sptps_log_quiet;
 319         }
 320 }
 321
 322 void reopenlogger(void) {
 323         if(logmode != LOGMODE_FILE) {
 324                 return;
 325         }
 326
 327         fflush(logfile);
 328         FILE *newfile = fopen(logfilename, "a");
 329
 330         if(!newfile) {
 331                 logger(DEBUG_ALWAYS, LOG_ERR, "Unable to reopen log file %s: %s", logfilename, strerror(errno));
 332                 return;
 333         }
 334
 335         fclose(logfile);
 336         logfile = newfile;
 337 }
 338
 339
 340 void closelogger(void) {
 341         switch(logmode) {
 342         case LOGMODE_FILE:
 343                 fclose(logfile);
 344                 break;
 345
 346         case LOGMODE_SYSLOG:
 347 #ifdef HAVE_WINDOWS
 348                 DeregisterEventSource(loghandle);
 349                 break;
 350 #else
 351 #ifdef HAVE_SYSLOG_H
 352                 closelog();
 353                 break;
 354 #endif
 355 #endif
 356
 357         case LOGMODE_NULL:
 358         case LOGMODE_STDERR:
 359         default:
 360                 break;
 361         }
 362 }