git.gag.com Git - fw/openocd/blob - src/helper/log.c

   1 /* SPDX-License-Identifier: GPL-2.0-or-later */
   2
   3 /***************************************************************************
   4  *   Copyright (C) 2005 by Dominic Rath                                    *
   5  *   Dominic.Rath@gmx.de                                                   *
   6  *                                                                         *
   7  *   Copyright (C) 2007-2010 Øyvind Harboe                                 *
   8  *   oyvind.harboe@zylin.com                                               *
   9  *                                                                         *
  10  *   Copyright (C) 2008 by Spencer Oliver                                  *
  11  *   spen@spen-soft.co.uk                                                  *
  12  ***************************************************************************/
  13
  14 #ifdef HAVE_CONFIG_H
  15 #include "config.h"
  16 #endif
  17
  18 #include "log.h"
  19 #include "command.h"
  20 #include "replacements.h"
  21 #include "time_support.h"
  22 #include <server/server.h>
  23
  24 #include <stdarg.h>
  25
  26 #ifdef _DEBUG_FREE_SPACE_
  27 #ifdef HAVE_MALLOC_H
  28 #include <malloc.h>
  29 #else
  30 #error "malloc.h is required to use --enable-malloc-logging"
  31 #endif
  32 #endif
  33
  34 int debug_level = LOG_LVL_INFO;
  35
  36 static FILE *log_output;
  37 static struct log_callback *log_callbacks;
  38
  39 static int64_t last_time;
  40
  41 static int64_t start;
  42
  43 static const char * const log_strings[6] = {
  44         "User : ",
  45         "Error: ",
  46         "Warn : ",      /* want a space after each colon, all same width, colons aligned */
  47         "Info : ",
  48         "Debug: ",
  49         "Debug: "
  50 };
  51
  52 static int count;
  53
  54 /* forward the log to the listeners */
  55 static void log_forward(const char *file, unsigned line, const char *function, const char *string)
  56 {
  57         struct log_callback *cb, *next;
  58         cb = log_callbacks;
  59         /* DANGER!!!! the log callback can remove itself!!!! */
  60         while (cb) {
  61                 next = cb->next;
  62                 cb->fn(cb->priv, file, line, function, string);
  63                 cb = next;
  64         }
  65 }
  66
  67 /* The log_puts() serves two somewhat different goals:
  68  *
  69  * - logging
  70  * - feeding low-level info to the user in GDB or Telnet
  71  *
  72  * The latter dictates that strings without newline are not logged, lest there
  73  * will be *MANY log lines when sending one char at the time(e.g.
  74  * target_request.c).
  75  *
  76  */
  77 static void log_puts(enum log_levels level,
  78         const char *file,
  79         int line,
  80         const char *function,
  81         const char *string)
  82 {
  83         char *f;
  84
  85         if (!log_output) {
  86                 /* log_init() not called yet; print on stderr */
  87                 fputs(string, stderr);
  88                 fflush(stderr);
  89                 return;
  90         }
  91
  92         if (level == LOG_LVL_OUTPUT) {
  93                 /* do not prepend any headers, just print out what we were given and return */
  94                 fputs(string, log_output);
  95                 fflush(log_output);
  96                 return;
  97         }
  98
  99         f = strrchr(file, '/');
 100         if (f)
 101                 file = f + 1;
 102
 103         if (debug_level >= LOG_LVL_DEBUG) {
 104                 /* print with count and time information */
 105                 int64_t t = timeval_ms() - start;
 106 #ifdef _DEBUG_FREE_SPACE_
 107                 struct mallinfo info;
 108                 info = mallinfo();
 109 #endif
 110                 fprintf(log_output, "%s%d %" PRId64 " %s:%d %s()"
 111 #ifdef _DEBUG_FREE_SPACE_
 112                         " %d"
 113 #endif
 114                         ": %s", log_strings[level + 1], count, t, file, line, function,
 115 #ifdef _DEBUG_FREE_SPACE_
 116                         info.fordblks,
 117 #endif
 118                         string);
 119         } else {
 120                 /* if we are using gdb through pipes then we do not want any output
 121                  * to the pipe otherwise we get repeated strings */
 122                 fprintf(log_output, "%s%s",
 123                         (level > LOG_LVL_USER) ? log_strings[level + 1] : "", string);
 124         }
 125
 126         fflush(log_output);
 127
 128         /* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */
 129         if (level <= LOG_LVL_INFO)
 130                 log_forward(file, line, function, string);
 131 }
 132
 133 void log_printf(enum log_levels level,
 134         const char *file,
 135         unsigned line,
 136         const char *function,
 137         const char *format,
 138         ...)
 139 {
 140         char *string;
 141         va_list ap;
 142
 143         count++;
 144         if (level > debug_level)
 145                 return;
 146
 147         va_start(ap, format);
 148
 149         string = alloc_vprintf(format, ap);
 150         if (string) {
 151                 log_puts(level, file, line, function, string);
 152                 free(string);
 153         }
 154
 155         va_end(ap);
 156 }
 157
 158 void log_vprintf_lf(enum log_levels level, const char *file, unsigned line,
 159                 const char *function, const char *format, va_list args)
 160 {
 161         char *tmp;
 162
 163         count++;
 164
 165         if (level > debug_level)
 166                 return;
 167
 168         tmp = alloc_vprintf(format, args);
 169
 170         if (!tmp)
 171                 return;
 172
 173         /*
 174          * Note: alloc_vprintf() guarantees that the buffer is at least one
 175          * character longer.
 176          */
 177         strcat(tmp, "\n");
 178         log_puts(level, file, line, function, tmp);
 179         free(tmp);
 180 }
 181
 182 void log_printf_lf(enum log_levels level,
 183         const char *file,
 184         unsigned line,
 185         const char *function,
 186         const char *format,
 187         ...)
 188 {
 189         va_list ap;
 190
 191         va_start(ap, format);
 192         log_vprintf_lf(level, file, line, function, format, ap);
 193         va_end(ap);
 194 }
 195
 196 COMMAND_HANDLER(handle_debug_level_command)
 197 {
 198         if (CMD_ARGC == 1) {
 199                 int new_level;
 200                 COMMAND_PARSE_NUMBER(int, CMD_ARGV[0], new_level);
 201                 if ((new_level > LOG_LVL_DEBUG_IO) || (new_level < LOG_LVL_SILENT)) {
 202                         LOG_ERROR("level must be between %d and %d", LOG_LVL_SILENT, LOG_LVL_DEBUG_IO);
 203                         return ERROR_COMMAND_SYNTAX_ERROR;
 204                 }
 205                 debug_level = new_level;
 206         } else if (CMD_ARGC > 1)
 207                 return ERROR_COMMAND_SYNTAX_ERROR;
 208
 209         command_print(CMD, "debug_level: %i", debug_level);
 210
 211         return ERROR_OK;
 212 }
 213
 214 COMMAND_HANDLER(handle_log_output_command)
 215 {
 216         if (CMD_ARGC == 0 || (CMD_ARGC == 1 && strcmp(CMD_ARGV[0], "default") == 0)) {
 217                 if (log_output != stderr && log_output) {
 218                         /* Close previous log file, if it was open and wasn't stderr. */
 219                         fclose(log_output);
 220                 }
 221                 log_output = stderr;
 222                 LOG_DEBUG("set log_output to default");
 223                 return ERROR_OK;
 224         }
 225         if (CMD_ARGC == 1) {
 226                 FILE *file = fopen(CMD_ARGV[0], "w");
 227                 if (!file) {
 228                         LOG_ERROR("failed to open output log '%s'", CMD_ARGV[0]);
 229                         return ERROR_FAIL;
 230                 }
 231                 if (log_output != stderr && log_output) {
 232                         /* Close previous log file, if it was open and wasn't stderr. */
 233                         fclose(log_output);
 234                 }
 235                 log_output = file;
 236                 LOG_DEBUG("set log_output to \"%s\"", CMD_ARGV[0]);
 237                 return ERROR_OK;
 238         }
 239
 240         return ERROR_COMMAND_SYNTAX_ERROR;
 241 }
 242
 243 static const struct command_registration log_command_handlers[] = {
 244         {
 245                 .name = "log_output",
 246                 .handler = handle_log_output_command,
 247                 .mode = COMMAND_ANY,
 248                 .help = "redirect logging to a file (default: stderr)",
 249                 .usage = "[file_name | \"default\"]",
 250         },
 251         {
 252                 .name = "debug_level",
 253                 .handler = handle_debug_level_command,
 254                 .mode = COMMAND_ANY,
 255                 .help = "Sets the verbosity level of debugging output. "
 256                         "0 shows errors only; 1 adds warnings; "
 257                         "2 (default) adds other info; 3 adds debugging; "
 258                         "4 adds extra verbose debugging.",
 259                 .usage = "number",
 260         },
 261         COMMAND_REGISTRATION_DONE
 262 };
 263
 264 int log_register_commands(struct command_context *cmd_ctx)
 265 {
 266         return register_commands(cmd_ctx, NULL, log_command_handlers);
 267 }
 268
 269 void log_init(void)
 270 {
 271         /* set defaults for daemon configuration,
 272          * if not set by cmdline or cfgfile */
 273         char *debug_env = getenv("OPENOCD_DEBUG_LEVEL");
 274         if (debug_env) {
 275                 int value;
 276                 int retval = parse_int(debug_env, &value);
 277                 if (retval == ERROR_OK &&
 278                                 debug_level >= LOG_LVL_SILENT &&
 279                                 debug_level <= LOG_LVL_DEBUG_IO)
 280                                 debug_level = value;
 281         }
 282
 283         if (!log_output)
 284                 log_output = stderr;
 285
 286         start = last_time = timeval_ms();
 287 }
 288
 289 void log_exit(void)
 290 {
 291         if (log_output && log_output != stderr) {
 292                 /* Close log file, if it was open and wasn't stderr. */
 293                 fclose(log_output);
 294         }
 295         log_output = NULL;
 296 }
 297
 298 int set_log_output(struct command_context *cmd_ctx, FILE *output)
 299 {
 300         log_output = output;
 301         return ERROR_OK;
 302 }
 303
 304 /* add/remove log callback handler */
 305 int log_add_callback(log_callback_fn fn, void *priv)
 306 {
 307         struct log_callback *cb;
 308
 309         /* prevent the same callback to be registered more than once, just for sure */
 310         for (cb = log_callbacks; cb; cb = cb->next) {
 311                 if (cb->fn == fn && cb->priv == priv)
 312                         return ERROR_COMMAND_SYNTAX_ERROR;
 313         }
 314
 315         /* alloc memory, it is safe just to return in case of an error, no need for the caller to
 316          *check this */
 317         cb = malloc(sizeof(struct log_callback));
 318         if (!cb)
 319                 return ERROR_BUF_TOO_SMALL;
 320
 321         /* add item to the beginning of the linked list */
 322         cb->fn = fn;
 323         cb->priv = priv;
 324         cb->next = log_callbacks;
 325         log_callbacks = cb;
 326
 327         return ERROR_OK;
 328 }
 329
 330 int log_remove_callback(log_callback_fn fn, void *priv)
 331 {
 332         struct log_callback *cb, **p;
 333
 334         for (p = &log_callbacks; (cb = *p); p = &(*p)->next) {
 335                 if (cb->fn == fn && cb->priv == priv) {
 336                         *p = cb->next;
 337                         free(cb);
 338                         return ERROR_OK;
 339                 }
 340         }
 341
 342         /* no such item */
 343         return ERROR_COMMAND_SYNTAX_ERROR;
 344 }
 345
 346 /* return allocated string w/printf() result */
 347 char *alloc_vprintf(const char *fmt, va_list ap)
 348 {
 349         va_list ap_copy;
 350         int len;
 351         char *string;
 352
 353         /* determine the length of the buffer needed */
 354         va_copy(ap_copy, ap);
 355         len = vsnprintf(NULL, 0, fmt, ap_copy);
 356         va_end(ap_copy);
 357
 358         /* allocate and make room for terminating zero. */
 359         /* FIXME: The old version always allocated at least one byte extra and
 360          * other code depend on that. They should be probably be fixed, but for
 361          * now reserve the extra byte. */
 362         string = malloc(len + 2);
 363         if (!string)
 364                 return NULL;
 365
 366         /* do the real work */
 367         vsnprintf(string, len + 1, fmt, ap);
 368
 369         return string;
 370 }
 371
 372 char *alloc_printf(const char *format, ...)
 373 {
 374         char *string;
 375         va_list ap;
 376         va_start(ap, format);
 377         string = alloc_vprintf(format, ap);
 378         va_end(ap);
 379         return string;
 380 }
 381
 382 /* Code must return to the server loop before 1000ms has returned or invoke
 383  * this function.
 384  *
 385  * The GDB connection will time out if it spends >2000ms and you'll get nasty
 386  * error messages from GDB:
 387  *
 388  * Ignoring packet error, continuing...
 389  * Reply contains invalid hex digit 116
 390  *
 391  * While it is possible use "set remotetimeout" to more than the default 2000ms
 392  * in GDB, OpenOCD guarantees that it sends keep-alive packages on the
 393  * GDB protocol and it is a bug in OpenOCD not to either return to the server
 394  * loop or invoke keep_alive() every 1000ms.
 395  *
 396  * This function will send a keep alive packet if >500ms has passed since last time
 397  * it was invoked.
 398  *
 399  * Note that this function can be invoked often, so it needs to be relatively
 400  * fast when invoked more often than every 500ms.
 401  *
 402  */
 403 #define KEEP_ALIVE_KICK_TIME_MS  500
 404 #define KEEP_ALIVE_TIMEOUT_MS   1000
 405
 406 static void gdb_timeout_warning(int64_t delta_time)
 407 {
 408         extern int gdb_actual_connections;
 409
 410         if (gdb_actual_connections)
 411                 LOG_WARNING("keep_alive() was not invoked in the "
 412                         "%d ms timelimit. GDB alive packet not "
 413                         "sent! (%" PRId64 " ms). Workaround: increase "
 414                         "\"set remotetimeout\" in GDB",
 415                         KEEP_ALIVE_TIMEOUT_MS,
 416                         delta_time);
 417         else
 418                 LOG_DEBUG("keep_alive() was not invoked in the "
 419                         "%d ms timelimit (%" PRId64 " ms). This may cause "
 420                         "trouble with GDB connections.",
 421                         KEEP_ALIVE_TIMEOUT_MS,
 422                         delta_time);
 423 }
 424
 425 void keep_alive(void)
 426 {
 427         int64_t current_time = timeval_ms();
 428         int64_t delta_time = current_time - last_time;
 429
 430         if (delta_time > KEEP_ALIVE_TIMEOUT_MS) {
 431                 last_time = current_time;
 432
 433                 gdb_timeout_warning(delta_time);
 434         }
 435
 436         if (delta_time > KEEP_ALIVE_KICK_TIME_MS) {
 437                 last_time = current_time;
 438
 439                 /* this will keep the GDB connection alive */
 440                 server_keep_clients_alive();
 441
 442                 /* DANGER!!!! do not add code to invoke e.g. target event processing,
 443                  * jim timer processing, etc. it can cause infinite recursion +
 444                  * jim event callbacks need to happen at a well defined time,
 445                  * not anywhere keep_alive() is invoked.
 446                  *
 447                  * These functions should be invoked at a well defined spot in server.c
 448                  */
 449         }
 450 }
 451
 452 /* reset keep alive timer without sending message */
 453 void kept_alive(void)
 454 {
 455         int64_t current_time = timeval_ms();
 456
 457         int64_t delta_time = current_time - last_time;
 458
 459         last_time = current_time;
 460
 461         if (delta_time > KEEP_ALIVE_TIMEOUT_MS)
 462                 gdb_timeout_warning(delta_time);
 463 }
 464
 465 /* if we sleep for extended periods of time, we must invoke keep_alive() intermittently */
 466 void alive_sleep(uint64_t ms)
 467 {
 468         uint64_t nap_time = 10;
 469         for (uint64_t i = 0; i < ms; i += nap_time) {
 470                 uint64_t sleep_a_bit = ms - i;
 471                 if (sleep_a_bit > nap_time)
 472                         sleep_a_bit = nap_time;
 473
 474                 usleep(sleep_a_bit * 1000);
 475                 keep_alive();
 476         }
 477 }
 478
 479 void busy_sleep(uint64_t ms)
 480 {
 481         uint64_t then = timeval_ms();
 482         while (timeval_ms() - then < ms) {
 483                 /*
 484                  * busy wait
 485                  */
 486         }
 487 }
 488
 489 /* Maximum size of socket error message retrieved from operation system */
 490 #define MAX_SOCKET_ERR_MSG_LENGTH 256
 491
 492 /* Provide log message for the last socket error.
 493    Uses errno on *nix and WSAGetLastError() on Windows */
 494 void log_socket_error(const char *socket_desc)
 495 {
 496         int error_code;
 497 #ifdef _WIN32
 498         error_code = WSAGetLastError();
 499         char error_message[MAX_SOCKET_ERR_MSG_LENGTH];
 500         error_message[0] = '\0';
 501         DWORD retval = FormatMessage(FORMAT_MESSAGE_FROM_SYSTEM, NULL, error_code, 0,
 502                 error_message, MAX_SOCKET_ERR_MSG_LENGTH, NULL);
 503         error_message[MAX_SOCKET_ERR_MSG_LENGTH - 1] = '\0';
 504         const bool have_message = (retval != 0) && (error_message[0] != '\0');
 505         LOG_ERROR("Error on socket '%s': WSAGetLastError==%d%s%s.", socket_desc, error_code,
 506                 (have_message ? ", message: " : ""),
 507                 (have_message ? error_message : ""));
 508 #else
 509         error_code = errno;
 510         LOG_ERROR("Error on socket '%s': errno==%d, message: %s.", socket_desc, error_code, strerror(error_code));
 511 #endif
 512 }
 513
 514 /**
 515  * Find the first non-printable character in the char buffer, return a pointer to it.
 516  * If no such character exists, return NULL.
 517  */
 518 char *find_nonprint_char(char *buf, unsigned buf_len)
 519 {
 520         for (unsigned int i = 0; i < buf_len; i++) {
 521                 if (!isprint(buf[i]))
 522                         return buf + i;
 523         }
 524         return NULL;
 525 }