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,2008 Ø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, write to the                         *
  23  *   Free Software Foundation, Inc.,                                       *
  24  *   59 Temple Place - Suite 330, Boston, MA  02111-1307, USA.             *
  25  ***************************************************************************/
  26 #ifdef HAVE_CONFIG_H
  27 #include "config.h"
  28 #endif
  29
  30 #include "log.h"
  31 #include "time_support.h"
  32 #include "server.h"
  33
  34 #include <stdarg.h>
  35
  36 #ifdef _DEBUG_FREE_SPACE_
  37 #ifdef HAVE_MALLOC_H
  38 #include <malloc.h>
  39 #else
  40 #error "malloc.h is required to use --enable-malloc-logging"
  41 #endif
  42 #endif
  43
  44 int debug_level = -1;
  45
  46 static FILE* log_output;
  47 static log_callback_t *log_callbacks = NULL;
  48
  49 static long long last_time;
  50 static long long current_time;
  51
  52 static long long start;
  53
  54 static char *log_strings[5] =
  55 {
  56         "User : ",
  57         "Error: ",
  58         "Warn : ",  /* want a space after each colon, all same width, colons aligned */
  59         "Info : ",
  60         "Debug: "
  61 };
  62
  63
  64 static int count = 0;
  65
  66 /* The log_puts() serves to somewhat different goals:
  67  *
  68  * - logging
  69  * - feeding low-level info to the user in GDB or Telnet
  70  *
  71  * The latter dictates that strings without newline are not logged, lest there
  72  * will be *MANY log lines when sending one char at the time(e.g.
  73  * target_request.c).
  74  *
  75  */
  76 static void log_puts(enum log_levels level, const char *file, int line, const char *function, const char *string)
  77 {
  78         char *f;
  79         if (level == LOG_LVL_OUTPUT)
  80         {
  81                 /* do not prepend any headers, just print out what we were given and return */
  82                 fputs(string, log_output);
  83                 fflush(log_output);
  84                 return;
  85         }
  86
  87         f = strrchr(file, '/');
  88         if (f != NULL)
  89                 file = f + 1;
  90
  91         if (strchr(string, '\n')!=NULL)
  92         {
  93                 if (debug_level >= LOG_LVL_DEBUG)
  94                 {
  95                         /* print with count and time information */
  96                         int t=(int)(timeval_ms()-start);
  97 #ifdef _DEBUG_FREE_SPACE_
  98                         struct mallinfo info;
  99                         info = mallinfo();
 100 #endif
 101                         fprintf(log_output, "%s%d %d %s:%d %s()"
 102 #ifdef _DEBUG_FREE_SPACE_
 103                                         " %d"
 104 #endif
 105                                         ": %s", log_strings[level+1], count, t, file, line, function,
 106 #ifdef _DEBUG_FREE_SPACE_
 107                                         info.fordblks,
 108 #endif
 109                                         string);
 110                 }
 111                 else if(server_use_pipes == 0)
 112                 {
 113                         /* if we are using gdb through pipes then we do not want any output
 114                          * to the pipe otherwise we get repeated strings */
 115                         if (strcmp(string, "\n") != 0)
 116                         {
 117                                 /* print human readable output - but skip empty lines */
 118                                 fprintf(log_output, "%s%s",
 119                                                 (level > LOG_LVL_USER)?log_strings[level+1]:"", string);
 120                         }
 121                 }
 122         } else
 123         {
 124                 /* only entire lines are logged. Otherwise it's
 125                  * single chars intended for the log callbacks. */
 126         }
 127
 128         fflush(log_output);
 129
 130         /* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */
 131         if (level <= LOG_LVL_INFO)
 132         {
 133                 log_callback_t *cb, *next;
 134                 cb = log_callbacks;
 135                 /* DANGER!!!! the log callback can remove itself!!!! */
 136                 while (cb)
 137                 {
 138                         next=cb->next;
 139                         cb->fn(cb->priv, file, line, function, string);
 140                         cb=next;
 141                 }
 142         }
 143 }
 144
 145 void log_printf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
 146 {
 147         char *string;
 148         va_list ap;
 149
 150         count++;
 151         if (level > debug_level)
 152                 return;
 153
 154         va_start(ap, format);
 155
 156         string = alloc_vprintf(format, ap);
 157         if (string != NULL)
 158         {
 159                 log_puts(level, file, line, function, string);
 160                 free(string);
 161         }
 162
 163         va_end(ap);
 164 }
 165
 166 void log_printf_lf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
 167 {
 168         char *string;
 169         va_list ap;
 170
 171         count++;
 172         if (level > debug_level)
 173                 return;
 174
 175         va_start(ap, format);
 176
 177         string = alloc_vprintf(format, ap);
 178         if (string != NULL)
 179         {
 180                 strcat(string, "\n"); /* alloc_vprintf guaranteed the buffer to be at least one char longer */
 181                 log_puts(level, file, line, function, string);
 182                 free(string);
 183         }
 184
 185         va_end(ap);
 186 }
 187
 188 /* change the current debug level on the fly
 189  * 0: only ERRORS
 190  * 1: + WARNINGS
 191  * 2: + INFORMATIONAL MSGS
 192  * 3: + DEBUG MSGS
 193  */
 194 int handle_debug_level_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc)
 195 {
 196         if (argc == 0)
 197                 command_print(cmd_ctx, "debug_level: %i", debug_level);
 198
 199         if (argc > 0)
 200                 debug_level = strtoul(args[0], NULL, 0);
 201
 202         if (debug_level < 0)
 203                 debug_level = 0;
 204
 205         if (debug_level > 3)
 206                 debug_level = 3;
 207
 208         if (debug_level >= LOG_LVL_DEBUG && server_use_pipes == 1)
 209         {
 210                 /* if we are enabling debug info then we need to write to a log file
 211                  * otherwise the pipe will get full and cause issues with gdb */
 212                 FILE* file = fopen("openocd.log", "w");
 213                 if (file)
 214                 {
 215                         log_output = file;
 216                         LOG_WARNING("enabling log output as we are using pipes");
 217                 }
 218         }
 219
 220         return ERROR_OK;
 221 }
 222
 223 int handle_log_output_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc)
 224 {
 225         if (argc == 1)
 226         {
 227                 FILE* file = fopen(args[0], "w");
 228
 229                 if (file)
 230                 {
 231                         log_output = file;
 232                 }
 233         }
 234
 235         return ERROR_OK;
 236 }
 237
 238 int log_register_commands(struct command_context_s *cmd_ctx)
 239 {
 240         start = timeval_ms();
 241         register_command(cmd_ctx, NULL, "log_output", handle_log_output_command,
 242                 COMMAND_ANY, "redirect logging to <file> (default: stderr)");
 243         register_command(cmd_ctx, NULL, "debug_level", handle_debug_level_command,
 244                 COMMAND_ANY, "adjust debug level <0-3>");
 245
 246         return ERROR_OK;
 247 }
 248
 249 int log_init(struct command_context_s *cmd_ctx)
 250 {
 251         /* set defaults for daemon configuration, if not set by cmdline or cfgfile */
 252         if (debug_level == -1)
 253                 debug_level = LOG_LVL_INFO;
 254
 255         if (log_output == NULL)
 256         {
 257                 log_output = stderr;
 258         }
 259
 260         start=last_time=timeval_ms();
 261
 262         return ERROR_OK;
 263 }
 264
 265 int set_log_output(struct command_context_s *cmd_ctx, FILE *output)
 266 {
 267         log_output = output;
 268         return ERROR_OK;
 269 }
 270
 271 /* add/remove log callback handler */
 272 int log_add_callback(log_callback_fn fn, void *priv)
 273 {
 274         log_callback_t *cb;
 275
 276         /* prevent the same callback to be registered more than once, just for sure */
 277         for (cb = log_callbacks; cb; cb = cb->next)
 278         {
 279                 if (cb->fn == fn && cb->priv == priv)
 280                         return ERROR_INVALID_ARGUMENTS;
 281         }
 282
 283         /* alloc memory, it is safe just to return in case of an error, no need for the caller to check this */
 284         if ((cb = malloc(sizeof(log_callback_t))) == NULL)
 285                 return ERROR_BUF_TOO_SMALL;
 286
 287         /* add item to the beginning of the linked list */
 288         cb->fn = fn;
 289         cb->priv = priv;
 290         cb->next = log_callbacks;
 291         log_callbacks = cb;
 292
 293         return ERROR_OK;
 294 }
 295
 296 int log_remove_callback(log_callback_fn fn, void *priv)
 297 {
 298         log_callback_t *cb, **p;
 299
 300         for (p = &log_callbacks; (cb = *p); p = &(*p)->next)
 301         {
 302                 if (cb->fn == fn && cb->priv == priv)
 303                 {
 304                         *p = cb->next;
 305                         free(cb);
 306                         return ERROR_OK;
 307                 }
 308         }
 309
 310         /* no such item */
 311         return ERROR_INVALID_ARGUMENTS;
 312 }
 313
 314 /* return allocated string w/printf() result */
 315 char *alloc_vprintf(const char *fmt, va_list ap)
 316 {
 317         /* no buffer at the beginning, force realloc to do the job */
 318         char *string = NULL;
 319
 320         /* start with buffer size suitable for typical messages */
 321         int size = 128;
 322
 323         for (;;)
 324         {
 325                 char *t = string;
 326                 va_list ap_copy;
 327                 int ret;
 328                 string = realloc(string, size);
 329                 if (string == NULL)
 330                 {
 331                         if (t != NULL)
 332                                 free(t);
 333                         return NULL;
 334                 }
 335
 336                 va_copy(ap_copy, ap);
 337
 338                 ret = vsnprintf(string, size, fmt, ap_copy);
 339                 /* NB! The result of the vsnprintf() might be an *EMPTY* string! */
 340                 if ((ret >= 0) && ((ret + 1) < size))
 341                         break;
 342
 343                 /* there was just enough or not enough space, allocate more in the next round */
 344                 size *= 2; /* double the buffer size */
 345         }
 346
 347         /* the returned buffer is by principle guaranteed to be at least one character longer */
 348         return string;
 349 }
 350
 351 char *alloc_printf(const char *format, ...)
 352 {
 353         char *string;
 354         va_list ap;
 355         va_start(ap, format);
 356         string = alloc_vprintf(format, ap);
 357         va_end(ap);
 358         return string;
 359 }
 360
 361 /* Code must return to the server loop before 1000ms has returned or invoke
 362  * this function.
 363  *
 364  * The GDB connection will time out if it spends >2000ms and you'll get nasty
 365  * error messages from GDB:
 366  *
 367  * Ignoring packet error, continuing...
 368  * Reply contains invalid hex digit 116
 369  *
 370  * While it is possible use "set remotetimeout" to more than the default 2000ms
 371  * in GDB, OpenOCD guarantees that it sends keep-alive packages on the
 372  * GDB protocol and it is a bug in OpenOCD not to either return to the server
 373  * loop or invoke keep_alive() every 1000ms.
 374  *
 375  * This function will send a keep alive packet if >500ms has passed since last time
 376  * it was invoked.
 377  *
 378  * Note that this function can be invoked often, so it needs to be relatively
 379  * fast when invoked more often than every 500ms.
 380  *
 381  */
 382 void keep_alive()
 383 {
 384         current_time=timeval_ms();
 385         if (current_time-last_time>1000)
 386         {
 387                 LOG_WARNING("keep_alive() was not invoked in the 1000ms timelimit. GDB alive packet not sent! (%lld). Workaround: increase \"set remotetimeout\" in GDB", current_time-last_time);
 388         }
 389         if (current_time-last_time>500)
 390         {
 391                 /* this will keep the GDB connection alive */
 392                 LOG_USER_N("%s", "");
 393
 394                 /* DANGER!!!! do not add code to invoke e.g. target event processing,
 395                  * jim timer processing, etc. it can cause infinite recursion +
 396                  * jim event callbacks need to happen at a well defined time,
 397                  * not anywhere keep_alive() is invoked.
 398                  *
 399                  * These functions should be invoked at a well defined spot in server.c
 400                  */
 401
 402                 last_time=current_time;
 403         }
 404 }
 405
 406 /* reset keep alive timer without sending message */
 407 void kept_alive()
 408 {
 409         current_time=timeval_ms();
 410         last_time=current_time;
 411 }
 412
 413 /* if we sleep for extended periods of time, we must invoke keep_alive() intermittantly */
 414 void alive_sleep(int ms)
 415 {
 416         int i;
 417         int napTime=10;
 418         for (i=0; i<ms; i+=napTime)
 419         {
 420                 int sleep_a_bit=ms-i;
 421                 if (sleep_a_bit>napTime)
 422                 {
 423                         sleep_a_bit=napTime;
 424                 }
 425                 usleep(sleep_a_bit*1000);
 426                 keep_alive();
 427         }
 428 }
 429
 430 void busy_sleep(int ms)
 431 {
 432         long long then;
 433         then=timeval_ms();
 434         while ((timeval_ms()-then)<ms)
 435         {
 436                 /* busy wait */
 437         }
 438 }