- Fixes '[+]=' whitespace
[fw/openocd] / src / helper / log.c
index cb45a7eb536d3c83df122dae86997fc56bfe3239..0e04af6f6bb88b7151e75b96dcdadb88344521e1 100644 (file)
@@ -2,6 +2,12 @@
  *   Copyright (C) 2005 by Dominic Rath                                    *
  *   Dominic.Rath@gmx.de                                                   *
  *                                                                         *
+ *   Copyright (C) 2007,2008 Ã˜yvind Harboe                                 *
+ *   oyvind.harboe@zylin.com                                               *
+ *                                                                         *
+ *   Copyright (C) 2008 by Spencer Oliver                                  *
+ *   spen@spen-soft.co.uk                                                  *
+ *                                                                         *
  *   This program is free software; you can redistribute it and/or modify  *
  *   it under the terms of the GNU General Public License as published by  *
  *   the Free Software Foundation; either version 2 of the License, or     *
 #endif
 
 #include "log.h"
-#include "configuration.h"
+#include "time_support.h"
+// @todo the inclusion of server.h here is a layering violation
+#include "server.h"
 
-#include <stdio.h>
-#include <stdlib.h>
-#include <string.h>
 #include <stdarg.h>
-#include <time.h>
+
+#ifdef _DEBUG_FREE_SPACE_
+#ifdef HAVE_MALLOC_H
+#include <malloc.h>
+#else
+#error "malloc.h is required to use --enable-malloc-logging"
+#endif
+#endif
 
 int debug_level = -1;
 
 static FILE* log_output;
 static log_callback_t *log_callbacks = NULL;
 
-static time_t start;
+static long long last_time;
+static long long current_time;
+
+static long long start;
 
 static char *log_strings[5] =
 {
-       "User:   ",
-       "Error:  ",
-       "Warning:",
-       "Info:   ",
-       "Debug:  "
+       "User : ",
+       "Error: ",
+       "Warn : ",  /* want a space after each colon, all same width, colons aligned */
+       "Info : ",
+       "Debug: "
 };
 
+
 static int count = 0;
 
 /* The log_puts() serves to somewhat different goals:
- * 
+ *
  * - logging
  * - feeding low-level info to the user in GDB or Telnet
- * 
+ *
  * The latter dictates that strings without newline are not logged, lest there
- * will be *MANY log lines when sending one char at the time(e.g. 
+ * will be *MANY log lines when sending one char at the time(e.g.
  * target_request.c).
- * 
+ *
  */
 static void log_puts(enum log_levels level, const char *file, int line, const char *function, const char *string)
 {
-       if (level == LOG_OUTPUT)
+       char *f;
+       if (level == LOG_LVL_OUTPUT)
        {
                /* do not prepend any headers, just print out what we were given and return */
                fputs(string, log_output);
@@ -68,33 +85,51 @@ static void log_puts(enum log_levels level, const char *file, int line, const ch
                return;
        }
 
-       char *f = strrchr(file, '/');
+       f = strrchr(file, '/');
        if (f != NULL)
                file = f + 1;
 
-       if (strchr(string, '\n')!=NULL)
+       if (strchr(string, '\n') != NULL)
        {
-               if (debug_level >= LOG_DEBUG)
+               if (debug_level >= LOG_LVL_DEBUG)
                {
                        /* print with count and time information */
-                       int t=(int)(time(NULL)-start);
-                       fprintf(log_output, "%s %d %d %s:%d %s(): %s", log_strings[level+1], count, t, file, line, function, string);
+                       int t=(int)(timeval_ms()-start);
+#ifdef _DEBUG_FREE_SPACE_
+                       struct mallinfo info;
+                       info = mallinfo();
+#endif
+                       fprintf(log_output, "%s%d %d %s:%d %s()"
+#ifdef _DEBUG_FREE_SPACE_
+                                       " %d"
+#endif
+                                       ": %s", log_strings[level+1], count, t, file, line, function,
+#ifdef _DEBUG_FREE_SPACE_
+                                       info.fordblks,
+#endif
+                                       string);
                }
-               else
+               else if (server_use_pipes == 0)
                {
-                       /* do not print count and time */
-                       fprintf(log_output, "%s %s:%d %s(): %s", log_strings[level+1], file, line, function, string);
+                       /* if we are using gdb through pipes then we do not want any output
+                        * to the pipe otherwise we get repeated strings */
+                       if (strcmp(string, "\n") != 0)
+                       {
+                               /* print human readable output - but skip empty lines */
+                               fprintf(log_output, "%s%s",
+                                               (level > LOG_LVL_USER)?log_strings[level+1]:"", string);
+                       }
                }
        } else
        {
-               /* only entire lines are logged. Otherwise it's 
+               /* only entire lines are logged. Otherwise it's
                 * single chars intended for the log callbacks. */
        }
 
        fflush(log_output);
-       
-       /* Never forward LOG_DEBUG, too verbose and they can be found in the log if need be */
-       if (level <= LOG_INFO)
+
+       /* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */
+       if (level <= LOG_LVL_INFO)
        {
                log_callback_t *cb, *next;
                cb = log_callbacks;
@@ -111,12 +146,12 @@ static void log_puts(enum log_levels level, const char *file, int line, const ch
 void log_printf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
 {
        char *string;
+       va_list ap;
 
        count++;
        if (level > debug_level)
                return;
 
-       va_list ap;
        va_start(ap, format);
 
        string = alloc_vprintf(format, ap);
@@ -125,21 +160,21 @@ void log_printf(enum log_levels level, const char *file, int line, const char *f
                log_puts(level, file, line, function, string);
                free(string);
        }
-       
+
        va_end(ap);
 }
 
 void log_printf_lf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
 {
        char *string;
+       va_list ap;
 
        count++;
        if (level > debug_level)
                return;
-       
-       va_list ap;
+
        va_start(ap, format);
-       
+
        string = alloc_vprintf(format, ap);
        if (string != NULL)
        {
@@ -147,7 +182,7 @@ void log_printf_lf(enum log_levels level, const char *file, int line, const char
                log_puts(level, file, line, function, string);
                free(string);
        }
-       
+
        va_end(ap);
 }
 
@@ -159,17 +194,30 @@ void log_printf_lf(enum log_levels level, const char *file, int line, const char
  */
 int handle_debug_level_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc)
 {
-       if (argc == 0)
-               command_print(cmd_ctx, "debug_level: %i", debug_level);
-
-       if (argc > 0)
-               debug_level = strtoul(args[0], NULL, 0);
+       if (argc == 1)
+       {
+               unsigned new_level;
+               int retval = parse_uint(args[0], &new_level);
+               if (ERROR_OK != retval)
+                       return retval;
+               debug_level = MIN(new_level, LOG_LVL_DEBUG);
+       }
+       else if (argc > 1)
+               return ERROR_COMMAND_SYNTAX_ERROR;
 
-       if (debug_level < 0)
-               debug_level = 0;
+       if (debug_level >= LOG_LVL_DEBUG && server_use_pipes == 1)
+       {
+               /* if we are enabling debug info then we need to write to a log file
+                * otherwise the pipe will get full and cause issues with gdb */
+               FILE* file = fopen("openocd.log", "w");
+               if (file)
+               {
+                       log_output = file;
+                       LOG_WARNING("enabling log output as we are using pipes");
+               }
+       }
 
-       if (debug_level > 3)
-               debug_level = 3;
+       command_print(cmd_ctx, "debug_level: %i", debug_level);
 
        return ERROR_OK;
 }
@@ -179,7 +227,7 @@ int handle_log_output_command(struct command_context_s *cmd_ctx, char *cmd, char
        if (argc == 1)
        {
                FILE* file = fopen(args[0], "w");
-               
+
                if (file)
                {
                        log_output = file;
@@ -191,7 +239,7 @@ int handle_log_output_command(struct command_context_s *cmd_ctx, char *cmd, char
 
 int log_register_commands(struct command_context_s *cmd_ctx)
 {
-       start = time(NULL);
+       start = timeval_ms();
        register_command(cmd_ctx, NULL, "log_output", handle_log_output_command,
                COMMAND_ANY, "redirect logging to <file> (default: stderr)");
        register_command(cmd_ctx, NULL, "debug_level", handle_debug_level_command,
@@ -204,16 +252,18 @@ int log_init(struct command_context_s *cmd_ctx)
 {
        /* set defaults for daemon configuration, if not set by cmdline or cfgfile */
        if (debug_level == -1)
-               debug_level = LOG_INFO;
-       
+               debug_level = LOG_LVL_INFO;
+
        if (log_output == NULL)
        {
                log_output = stderr;
        }
-       
+
+       start=last_time=timeval_ms();
+
        return ERROR_OK;
 }
-       
+
 int set_log_output(struct command_context_s *cmd_ctx, FILE *output)
 {
        log_output = output;
@@ -268,13 +318,15 @@ char *alloc_vprintf(const char *fmt, va_list ap)
 {
        /* no buffer at the beginning, force realloc to do the job */
        char *string = NULL;
-       
+
        /* start with buffer size suitable for typical messages */
        int size = 128;
 
        for (;;)
        {
                char *t = string;
+               va_list ap_copy;
+               int ret;
                string = realloc(string, size);
                if (string == NULL)
                {
@@ -283,10 +335,8 @@ char *alloc_vprintf(const char *fmt, va_list ap)
                        return NULL;
                }
 
-               va_list ap_copy;
                va_copy(ap_copy, ap);
 
-               int ret;
                ret = vsnprintf(string, size, fmt, ap_copy);
                /* NB! The result of the vsnprintf() might be an *EMPTY* string! */
                if ((ret >= 0) && ((ret + 1) < size))
@@ -295,7 +345,7 @@ char *alloc_vprintf(const char *fmt, va_list ap)
                /* there was just enough or not enough space, allocate more in the next round */
                size *= 2; /* double the buffer size */
        }
-       
+
        /* the returned buffer is by principle guaranteed to be at least one character longer */
        return string;
 }
@@ -309,3 +359,94 @@ char *alloc_printf(const char *format, ...)
        va_end(ap);
        return string;
 }
+
+/* Code must return to the server loop before 1000ms has returned or invoke
+ * this function.
+ *
+ * The GDB connection will time out if it spends >2000ms and you'll get nasty
+ * error messages from GDB:
+ *
+ * Ignoring packet error, continuing...
+ * Reply contains invalid hex digit 116
+ *
+ * While it is possible use "set remotetimeout" to more than the default 2000ms
+ * in GDB, OpenOCD guarantees that it sends keep-alive packages on the
+ * GDB protocol and it is a bug in OpenOCD not to either return to the server
+ * loop or invoke keep_alive() every 1000ms.
+ *
+ * This function will send a keep alive packet if >500ms has passed since last time
+ * it was invoked.
+ *
+ * Note that this function can be invoked often, so it needs to be relatively
+ * fast when invoked more often than every 500ms.
+ *
+ */
+void keep_alive()
+{
+       current_time=timeval_ms();
+       if (current_time-last_time>1000)
+       {
+               extern int gdb_actual_connections;
+
+               if (gdb_actual_connections)
+                       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);
+               else
+                       LOG_DEBUG("keep_alive() was not invoked in the "
+                               "1000ms timelimit (%lld). This may cause "
+                               "trouble with GDB connections.",
+                               current_time-last_time);
+       }
+       if (current_time-last_time>500)
+       {
+               /* this will keep the GDB connection alive */
+               LOG_USER_N("%s", "");
+
+               /* DANGER!!!! do not add code to invoke e.g. target event processing,
+                * jim timer processing, etc. it can cause infinite recursion +
+                * jim event callbacks need to happen at a well defined time,
+                * not anywhere keep_alive() is invoked.
+                *
+                * These functions should be invoked at a well defined spot in server.c
+                */
+
+               last_time=current_time;
+       }
+}
+
+/* reset keep alive timer without sending message */
+void kept_alive()
+{
+       current_time=timeval_ms();
+       last_time=current_time;
+}
+
+/* if we sleep for extended periods of time, we must invoke keep_alive() intermittantly */
+void alive_sleep(int ms)
+{
+       int i;
+       int napTime=10;
+       for (i=0; i<ms; i += napTime)
+       {
+               int sleep_a_bit=ms-i;
+               if (sleep_a_bit>napTime)
+               {
+                       sleep_a_bit=napTime;
+               }
+               usleep(sleep_a_bit*1000);
+               keep_alive();
+       }
+}
+
+void busy_sleep(int ms)
+{
+       long long then;
+       then=timeval_ms();
+       while ((timeval_ms()-then)<ms)
+       {
+               /* busy wait */
+       }
+}