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