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