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