X-Git-Url: https://review.openocd.org/gitweb?p=openocd.git;a=blobdiff_plain;f=src%2Fhelper%2Flog.c;h=f9807747b5f4f780743e2d871f9ace0022b2cb18;hp=de74f9d05c5069b6315cce3bd15b23ed0d7be03f;hb=8f47a09cc55a1d2030b7d0df11668b6cb4f2a905;hpb=0a749feb8e05d41b22a75e5545233b3e400463f8 diff --git a/src/helper/log.c b/src/helper/log.c index de74f9d05c..f9807747b5 100644 --- a/src/helper/log.c +++ b/src/helper/log.c @@ -2,6 +2,12 @@ * Copyright (C) 2005 by Dominic Rath * * Dominic.Rath@gmx.de * * * + * Copyright (C) 2007-2010 Ø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 * @@ -13,206 +19,273 @@ * GNU General Public License for more details. * * * * You should have received a copy of the GNU General Public License * - * along with this program; if not, write to the * - * Free Software Foundation, Inc., * - * 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA. * + * along with this program. If not, see . * ***************************************************************************/ + #ifdef HAVE_CONFIG_H #include "config.h" #endif #include "log.h" -#include "configuration.h" +#include "command.h" +#include "time_support.h" -#include -#include -#include #include -#include + +#ifdef _DEBUG_FREE_SPACE_ +#ifdef HAVE_MALLOC_H +#include +#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 FILE *log_output; +static struct log_callback *log_callbacks; -static time_t start; +static int64_t last_time; +static int64_t current_time; -static char *log_strings[5] = -{ - "User: ", - "Error: ", - "Warning:", - "Info: ", - "Debug: " +static int64_t start; + +static const char * const log_strings[6] = { + "User : ", + "Error: ", + "Warn : ", /* want a space after each colon, all same width, colons aligned */ + "Info : ", + "Debug: ", + "Debug: " }; -static int count = 0; +static int count; + +/* forward the log to the listeners */ +static void log_forward(const char *file, unsigned line, const char *function, const char *string) +{ + struct log_callback *cb, *next; + cb = log_callbacks; + /* DANGER!!!! the log callback can remove itself!!!! */ + while (cb) { + next = cb->next; + cb->fn(cb->priv, file, line, function, string); + cb = next; + } +} -/* The log_printfv() serves to somewhat different goals: - * +/* The log_puts() serves two 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) +static void log_puts(enum log_levels level, + const char *file, + int line, + const char *function, + const char *string) { - log_callback_t *cb; - - 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); fflush(log_output); return; } - char *f = strrchr(file, '/'); + f = strrchr(file, '/'); if (f != NULL) file = f + 1; - if (strchr(buffer, '\n')!=NULL) - { - if (debug_level >= LOG_DEBUG) - { + if (strlen(string) > 0) { + 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); - } - else - { - /* do not print count and time */ - fprintf(log_output, "%s %s:%d %s(): %s", log_strings[level+1], file, line, function, string); + int64_t t = timeval_ms() - start; +#ifdef _DEBUG_FREE_SPACE_ + struct mallinfo info; + info = mallinfo(); +#endif + fprintf(log_output, "%s%d %" PRId64 " %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 { + /* if we are using gdb through pipes then we do not want any output + * to the pipe otherwise we get repeated strings */ + fprintf(log_output, "%s%s", + (level > LOG_LVL_USER) ? log_strings[level + 1] : "", string); } - } else - { - /* only entire lines are logged. Otherwise it's - * single chars intended for the log callbacks. */ + } else { + /* Empty strings are sent to log callbacks to keep e.g. gdbserver alive, here we do + *nothing. */ } fflush(log_output); - - /* Never forward LOG_DEBUG, too verbose and they can be found in the log if need be */ - if (level <= LOG_INFO) - { - log_callback_t *cb; - for (cb = log_callbacks; cb; cb = cb->next) - { - cb->fn(cb->priv, file, line, function, string); - } - } + + /* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */ + if (level <= LOG_LVL_INFO) + log_forward(file, line, function, string); } -void log_printf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...) +void log_printf(enum log_levels level, + const char *file, + unsigned 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_printf(format, ap); - if (string != NULL) - { + string = alloc_vprintf(format, ap); + if (string != NULL) { 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, ...) +void log_vprintf_lf(enum log_levels level, const char *file, unsigned line, + const char *function, const char *format, va_list args) { - char *string; + char *tmp; count++; + if (level > debug_level) return; - + + tmp = alloc_vprintf(format, args); + + if (!tmp) + return; + + /* + * Note: alloc_vprintf() guarantees that the buffer is at least one + * character longer. + */ + strcat(tmp, "\n"); + log_puts(level, file, line, function, tmp); + free(tmp); +} + +void log_printf_lf(enum log_levels level, + const char *file, + unsigned line, + const char *function, + const char *format, + ...) +{ va_list ap; + va_start(ap, format); - - string = alloc_printf(format, ap); - if (string != NULL) - { - strcat(string, "\n"); /* alloc_printf guaranteed the buffer to be at least one char longer */ - log_puts(level, file, line, function, string); - free(string); - } - + log_vprintf_lf(level, file, line, function, format, ap); va_end(ap); } -/* change the current debug level on the fly - * 0: only ERRORS - * 1: + WARNINGS - * 2: + INFORMATIONAL MSGS - * 3: + DEBUG MSGS - */ -int handle_debug_level_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc) +COMMAND_HANDLER(handle_debug_level_command) { - if (argc == 0) - command_print(cmd_ctx, "debug_level: %i", debug_level); - - if (argc > 0) - debug_level = strtoul(args[0], NULL, 0); - - if (debug_level < 0) - debug_level = 0; + if (CMD_ARGC == 1) { + int new_level; + COMMAND_PARSE_NUMBER(int, CMD_ARGV[0], new_level); + if ((new_level > LOG_LVL_DEBUG_IO) || (new_level < LOG_LVL_SILENT)) { + LOG_ERROR("level must be between %d and %d", LOG_LVL_SILENT, LOG_LVL_DEBUG_IO); + return ERROR_COMMAND_SYNTAX_ERROR; + } + debug_level = new_level; + } else if (CMD_ARGC > 1) + return ERROR_COMMAND_SYNTAX_ERROR; - if (debug_level > 3) - debug_level = 3; + command_print(CMD_CTX, "debug_level: %i", debug_level); return ERROR_OK; } -int handle_log_output_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc) +COMMAND_HANDLER(handle_log_output_command) { - if (argc == 1) - { - FILE* file = fopen(args[0], "w"); - - if (file) - { - log_output = file; + if (CMD_ARGC == 1) { + FILE *file = fopen(CMD_ARGV[0], "w"); + if (file == NULL) { + LOG_ERROR("failed to open output log '%s'", CMD_ARGV[0]); + return ERROR_FAIL; + } + if (log_output != stderr && log_output != NULL) { + /* Close previous log file, if it was open and wasn't stderr. */ + fclose(log_output); } + log_output = file; } return ERROR_OK; } -int log_register_commands(struct command_context_s *cmd_ctx) -{ - start = time(NULL); - register_command(cmd_ctx, NULL, "log_output", handle_log_output_command, - COMMAND_ANY, "redirect logging to (default: stderr)"); - register_command(cmd_ctx, NULL, "debug_level", handle_debug_level_command, - COMMAND_ANY, "adjust debug level <0-3>"); +static struct command_registration log_command_handlers[] = { + { + .name = "log_output", + .handler = handle_log_output_command, + .mode = COMMAND_ANY, + .help = "redirect logging to a file (default: stderr)", + .usage = "file_name", + }, + { + .name = "debug_level", + .handler = handle_debug_level_command, + .mode = COMMAND_ANY, + .help = "Sets the verbosity level of debugging output. " + "0 shows errors only; 1 adds warnings; " + "2 (default) adds other info; 3 adds debugging; " + "4 adds extra verbose debugging.", + .usage = "number", + }, + COMMAND_REGISTRATION_DONE +}; - return ERROR_OK; +int log_register_commands(struct command_context *cmd_ctx) +{ + return register_commands(cmd_ctx, NULL, log_command_handlers); } -int log_init(struct command_context_s *cmd_ctx) +void log_init(void) { - /* set defaults for daemon configuration, if not set by cmdline or cfgfile */ + /* 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; + + char *debug_env = getenv("OPENOCD_DEBUG_LEVEL"); + if (NULL != debug_env) { + int value; + int retval = parse_int(debug_env, &value); + if (ERROR_OK == retval && + debug_level >= LOG_LVL_SILENT && + debug_level <= LOG_LVL_DEBUG_IO) + debug_level = value; + } + if (log_output == NULL) - { log_output = stderr; - } - - return ERROR_OK; + + start = last_time = timeval_ms(); } - -int set_log_output(struct command_context_s *cmd_ctx, FILE *output) + +int set_log_output(struct command_context *cmd_ctx, FILE *output) { log_output = output; return ERROR_OK; @@ -221,17 +294,18 @@ int set_log_output(struct command_context_s *cmd_ctx, FILE *output) /* add/remove log callback handler */ int log_add_callback(log_callback_fn fn, void *priv) { - log_callback_t *cb; + struct log_callback *cb; /* prevent the same callback to be registered more than once, just for sure */ - for (cb = log_callbacks; cb; cb = cb->next) - { + for (cb = log_callbacks; cb; cb = cb->next) { if (cb->fn == fn && cb->priv == priv) - return ERROR_INVALID_ARGUMENTS; + return ERROR_COMMAND_SYNTAX_ERROR; } - /* alloc memory, it is safe just to return in case of an error, no need for the caller to check this */ - if ((cb = malloc(sizeof(log_callback_t))) == NULL) + /* alloc memory, it is safe just to return in case of an error, no need for the caller to + *check this */ + cb = malloc(sizeof(struct log_callback)); + if (cb == NULL) return ERROR_BUF_TOO_SMALL; /* add item to the beginning of the linked list */ @@ -245,53 +319,138 @@ int log_add_callback(log_callback_fn fn, void *priv) int log_remove_callback(log_callback_fn fn, void *priv) { - log_callback_t *cb, **p; + struct log_callback *cb, **p; - for (p = &log_callbacks; (cb = *p); p = &(*p)->next) - { - if (cb->fn == fn && cb->priv == priv) - { - *p = cb->next; + for (p = &log_callbacks; (cb = *p); p = &(*p)->next) { + if (cb->fn == fn && cb->priv == priv) { + *p = cb->next; free(cb); return ERROR_OK; } } /* no such item */ - return ERROR_INVALID_ARGUMENTS; + return ERROR_COMMAND_SYNTAX_ERROR; } /* return allocated string w/printf() result */ -char *alloc_printf(const char *fmt, va_list ap) +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 minimal length to exercise all the code paths */ - int size = 1; + va_list ap_copy; + int len; + char *string; - for (;;) - { - size *= 2; /* double the buffer size */ - - char *t = string; - string = realloc(string, size); - if (string == NULL) - { - if (t != NULL) - free(t); - return NULL; - } - - int ret; - ret = vsnprintf(string, size, fmt, ap); - /* NB! The result of the vsnprintf() might be an *EMPTY* string! */ - if ((ret >= 0) && ((ret + 1) < size)) - break; - - /* there was just enough or not enough space, allocate more in the next round */ + /* determine the length of the buffer needed */ + va_copy(ap_copy, ap); + len = vsnprintf(NULL, 0, fmt, ap_copy); + va_end(ap_copy); + + /* allocate and make room for terminating zero. */ + /* FIXME: The old version always allocated at least one byte extra and + * other code depend on that. They should be probably be fixed, but for + * now reserve the extra byte. */ + string = malloc(len + 2); + if (string == NULL) + return NULL; + + /* do the real work */ + vsnprintf(string, len + 1, fmt, ap); + + return string; +} + +char *alloc_printf(const char *format, ...) +{ + char *string; + va_list ap; + va_start(ap, format); + string = alloc_vprintf(format, ap); + 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! (%" PRId64 "). Workaround: increase " + "\"set remotetimeout\" in GDB", + current_time-last_time); + else + LOG_DEBUG("keep_alive() was not invoked in the " + "1000ms timelimit (%" PRId64 "). 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(uint64_t ms) +{ + uint64_t napTime = 10; + for (uint64_t i = 0; i < ms; i += napTime) { + uint64_t sleep_a_bit = ms - i; + if (sleep_a_bit > napTime) + sleep_a_bit = napTime; + + usleep(sleep_a_bit * 1000); + keep_alive(); + } +} + +void busy_sleep(uint64_t ms) +{ + uint64_t then = timeval_ms(); + while (timeval_ms() - then < ms) { + /* + * busy wait + */ } - - /* the returned buffer is by principle guaranteed to be at least one character longer */ - return string; }