git.sur5r.net Git - openocd/blob - src/helper/log.c

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