X-Git-Url: https://review.openocd.org/gitweb?a=blobdiff_plain;f=src%2Fhelper%2Flog.c;h=8f48b928b5640791b1fd757be7d1150bdb24a742;hb=HEAD;hp=fa66de065966de85f54c238f4275c790615118fc;hpb=4668bd264cfe64c3e3ddd0f75cb5bf2e5e85f717;p=openocd.git diff --git a/src/helper/log.c b/src/helper/log.c index fa66de0659..471069adee 100644 --- a/src/helper/log.c +++ b/src/helper/log.c @@ -1,3 +1,5 @@ +// SPDX-License-Identifier: GPL-2.0-or-later + /*************************************************************************** * Copyright (C) 2005 by Dominic Rath * * Dominic.Rath@gmx.de * @@ -7,28 +9,17 @@ * * * 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 * - * (at your option) any later version. * - * * - * This program is distributed in the hope that it will be useful, * - * but WITHOUT ANY WARRANTY; without even the implied warranty of * - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * - * 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. * ***************************************************************************/ + #ifdef HAVE_CONFIG_H #include "config.h" #endif +#include "log.h" +#include "command.h" +#include "replacements.h" #include "time_support.h" -// @todo the inclusion of server.h here is a layering violation +#include #include #include @@ -41,80 +32,40 @@ #endif #endif -int debug_level = -1; +int debug_level = LOG_LVL_INFO; -static FILE* log_output; -static struct log_callback *log_callbacks = NULL; +static FILE *log_output; +static struct log_callback *log_callbacks; -static long long last_time; -static long long current_time; +static int64_t last_time; -static long long start; +static int64_t start; -static char *log_strings[5] = -{ +static const char * const log_strings[6] = { "User : ", "Error: ", - "Warn : ", /* want a space after each colon, all same width, colons aligned */ + "Warn : ", /* want a space after each colon, all same width, colons aligned */ "Info : ", + "Debug: ", "Debug: " }; +static int count; -static int count = 0; - - -static struct store_log_forward * log_head = NULL; -static int log_forward_count = 0; - -struct store_log_forward -{ - struct store_log_forward * next; - const char * file; - int line; - const char * function; - const char * string; -}; - -/* either forward the log to the listeners or store it for possible forwarding later */ +/* forward the log to the listeners */ static void log_forward(const char *file, unsigned line, const char *function, const char *string) { - if (log_forward_count==0) - { - 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; - } - } else - { - struct store_log_forward *log = malloc(sizeof (struct store_log_forward)); - log->file = strdup(file); - log->line = line; - log->function = strdup(function); - log->string = strdup(string); - log->next = NULL; - if (log_head==NULL) - log_head = log; - else - { - /* append to tail */ - struct store_log_forward * t; - t = log_head; - while (t->next!=NULL) - { - t = t->next; - } - t->next = log; - } + 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_puts() 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 @@ -124,11 +75,22 @@ static void log_forward(const char *file, unsigned line, const char *function, c * 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) { char *f; - if (level == LOG_LVL_OUTPUT) - { + + if (!log_output) { + /* log_init() not called yet; print on stderr */ + fputs(string, stderr); + fflush(stderr); + return; + } + + 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); @@ -136,52 +98,45 @@ static void log_puts(enum log_levels level, const char *file, int line, const ch } f = strrchr(file, '/'); - if (f != NULL) + if (f) file = f + 1; - if (strlen(string) > 0) - { - if (debug_level >= LOG_LVL_DEBUG) - { - /* print with count and time information */ - int t = (int)(timeval_ms()-start); + if (debug_level >= LOG_LVL_DEBUG) { + /* print with count and time information */ + int64_t t = timeval_ms() - start; #ifdef _DEBUG_FREE_SPACE_ - struct mallinfo info; - info = mallinfo(); + struct mallinfo info; + info = mallinfo(); #endif - fprintf(log_output, "%s%d %d %s:%d %s()" + fprintf(log_output, "%s%d %" PRId64 " %s:%d %s()" #ifdef _DEBUG_FREE_SPACE_ - " %d" + " %d" #endif - ": %s", log_strings[level + 1], count, t, file, line, function, + ": %s", log_strings[level + 1], count, t, file, line, function, #ifdef _DEBUG_FREE_SPACE_ - info.fordblks, + 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 - { - /* Empty strings are sent to log callbacks to keep e.g. gdbserver alive, here we do nothing. */ + 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); } fflush(log_output); /* 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, unsigned 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; @@ -193,8 +148,7 @@ void log_printf(enum log_levels level, const char *file, unsigned line, const ch va_start(ap, format); string = alloc_vprintf(format, ap); - if (string != NULL) - { + if (string) { log_puts(level, file, line, function, string); free(string); } @@ -202,71 +156,95 @@ void log_printf(enum log_levels level, const char *file, unsigned line, const ch va_end(ap); } -void log_printf_lf(enum log_levels level, const char *file, unsigned 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; - va_list ap; + char *tmp; count++; + if (level > debug_level) return; - va_start(ap, format); + tmp = alloc_vprintf(format, args); - string = alloc_vprintf(format, ap); - if (string != NULL) - { - strcat(string, "\n"); /* alloc_vprintf guaranteed the buffer to be at least one char longer */ - log_puts(level, file, line, function, string); - free(string); - } + 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); + log_vprintf_lf(level, file, line, function, format, ap); va_end(ap); } COMMAND_HANDLER(handle_debug_level_command) { - if (CMD_ARGC == 1) - { + if (CMD_ARGC == 1) { int new_level; COMMAND_PARSE_NUMBER(int, CMD_ARGV[0], new_level); - if ((debug_level > LOG_LVL_DEBUG) || (new_level < LOG_LVL_SILENT)) - { - LOG_ERROR("level must be between %d and %d", LOG_LVL_SILENT, LOG_LVL_DEBUG); + 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) + } else if (CMD_ARGC > 1) return ERROR_COMMAND_SYNTAX_ERROR; - command_print(CMD_CTX, "debug_level: %i", debug_level); + command_print(CMD, "debug_level: %i", debug_level); return ERROR_OK; } COMMAND_HANDLER(handle_log_output_command) { - if (CMD_ARGC == 1) - { - FILE* file = fopen(CMD_ARGV[0], "w"); + if (CMD_ARGC > 1) + return ERROR_COMMAND_SYNTAX_ERROR; - if (file) - { - log_output = file; + FILE *file; + if (CMD_ARGC == 1 && strcmp(CMD_ARGV[0], "default") != 0) { + file = fopen(CMD_ARGV[0], "w"); + if (!file) { + command_print(CMD, "failed to open output log \"%s\"", CMD_ARGV[0]); + return ERROR_FAIL; } + command_print(CMD, "set log_output to \"%s\"", CMD_ARGV[0]); + } else { + file = stderr; + command_print(CMD, "set log_output to default"); } + if (log_output != stderr && log_output) { + /* Close previous log file, if it was open and wasn't stderr. */ + fclose(log_output); + } + log_output = file; return ERROR_OK; } -static struct command_registration log_command_handlers[] = { +static const 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", + .usage = "[file_name | 'default']", }, { .name = "debug_level", @@ -274,7 +252,8 @@ static struct command_registration log_command_handlers[] = { .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.", + "2 (default) adds other info; 3 adds debugging; " + "4 adds extra verbose debugging.", .usage = "number", }, COMMAND_REGISTRATION_DONE @@ -289,32 +268,29 @@ void log_init(void) { /* set defaults for daemon configuration, * if not set by cmdline or cfgfile */ - if (debug_level == -1) - debug_level = LOG_LVL_INFO; - char *debug_env = getenv("OPENOCD_DEBUG_LEVEL"); - if (NULL != debug_env) - { + if (debug_env) { int value; int retval = parse_int(debug_env, &value); - if (ERROR_OK == retval && + if (retval == ERROR_OK && debug_level >= LOG_LVL_SILENT && - debug_level <= LOG_LVL_DEBUG) - { - debug_level = value; - } + debug_level <= LOG_LVL_DEBUG_IO) + debug_level = value; } - if (log_output == NULL) + if (!log_output) log_output = stderr; start = last_time = timeval_ms(); } -int set_log_output(struct command_context *cmd_ctx, FILE *output) +void log_exit(void) { - log_output = output; - return ERROR_OK; + if (log_output && log_output != stderr) { + /* Close log file, if it was open and wasn't stderr. */ + fclose(log_output); + } + log_output = NULL; } /* add/remove log callback handler */ @@ -323,14 +299,15 @@ int log_add_callback(log_callback_fn fn, void *priv) 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_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(struct log_callback))) == 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) return ERROR_BUF_TOO_SMALL; /* add item to the beginning of the linked list */ @@ -346,10 +323,8 @@ int log_remove_callback(log_callback_fn fn, void *priv) { struct log_callback *cb, **p; - for (p = &log_callbacks; (cb = *p); p = &(*p)->next) - { - if (cb->fn == fn && cb->priv == priv) - { + for (p = &log_callbacks; (cb = *p); p = &(*p)->next) { + if (cb->fn == fn && cb->priv == priv) { *p = cb->next; free(cb); return ERROR_OK; @@ -377,7 +352,7 @@ char *alloc_vprintf(const char *fmt, va_list ap) * 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) + if (!string) return NULL; /* do the real work */ @@ -417,29 +392,42 @@ char *alloc_printf(const char *format, ...) * fast when invoked more often than every 500ms. * */ -void keep_alive() +#define KEEP_ALIVE_KICK_TIME_MS 500 +#define KEEP_ALIVE_TIMEOUT_MS 1000 + +static void gdb_timeout_warning(int64_t delta_time) { - 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 (gdb_get_actual_connections()) + LOG_WARNING("keep_alive() was not invoked in the " + "%d ms timelimit. GDB alive packet not " + "sent! (%" PRId64 " ms). Workaround: increase " + "\"set remotetimeout\" in GDB", + KEEP_ALIVE_TIMEOUT_MS, + delta_time); + else + LOG_DEBUG("keep_alive() was not invoked in the " + "%d ms timelimit (%" PRId64 " ms). This may cause " + "trouble with GDB connections.", + KEEP_ALIVE_TIMEOUT_MS, + delta_time); +} + +void keep_alive(void) +{ + int64_t current_time = timeval_ms(); + int64_t delta_time = current_time - last_time; + + if (delta_time > KEEP_ALIVE_TIMEOUT_MS) { + last_time = current_time; + + gdb_timeout_warning(delta_time); } - if (current_time-last_time > 500) - { + + if (delta_time > KEEP_ALIVE_KICK_TIME_MS) { + last_time = current_time; + /* this will keep the GDB connection alive */ - LOG_USER_N("%s", ""); + server_keep_clients_alive(); /* DANGER!!!! do not add code to invoke e.g. target event processing, * jim timer processing, etc. it can cause infinite recursion + @@ -448,27 +436,30 @@ void keep_alive() * * 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() +void kept_alive(void) { - current_time = timeval_ms(); + int64_t current_time = timeval_ms(); + + int64_t delta_time = current_time - last_time; + last_time = current_time; + + if (delta_time > KEEP_ALIVE_TIMEOUT_MS) + gdb_timeout_warning(delta_time); } -/* if we sleep for extended periods of time, we must invoke keep_alive() intermittantly */ +/* if we sleep for extended periods of time, we must invoke keep_alive() intermittently */ void alive_sleep(uint64_t ms) { - uint64_t napTime = 10; - for (uint64_t i = 0; i < ms; i += napTime) - { + uint64_t nap_time = 10; + for (uint64_t i = 0; i < ms; i += nap_time) { uint64_t sleep_a_bit = ms - i; - if (sleep_a_bit > napTime) - sleep_a_bit = napTime; + if (sleep_a_bit > nap_time) + sleep_a_bit = nap_time; usleep(sleep_a_bit * 1000); keep_alive(); @@ -478,8 +469,47 @@ void alive_sleep(uint64_t ms) void busy_sleep(uint64_t ms) { uint64_t then = timeval_ms(); - while (timeval_ms() - then < ms) - { - /* busy wait */ + while (timeval_ms() - then < ms) { + /* + * busy wait + */ + } +} + +/* Maximum size of socket error message retrieved from operation system */ +#define MAX_SOCKET_ERR_MSG_LENGTH 256 + +/* Provide log message for the last socket error. + Uses errno on *nix and WSAGetLastError() on Windows */ +void log_socket_error(const char *socket_desc) +{ + int error_code; +#ifdef _WIN32 + error_code = WSAGetLastError(); + char error_message[MAX_SOCKET_ERR_MSG_LENGTH]; + error_message[0] = '\0'; + DWORD retval = FormatMessage(FORMAT_MESSAGE_FROM_SYSTEM, NULL, error_code, 0, + error_message, MAX_SOCKET_ERR_MSG_LENGTH, NULL); + error_message[MAX_SOCKET_ERR_MSG_LENGTH - 1] = '\0'; + const bool have_message = (retval != 0) && (error_message[0] != '\0'); + LOG_ERROR("Error on socket '%s': WSAGetLastError==%d%s%s.", socket_desc, error_code, + (have_message ? ", message: " : ""), + (have_message ? error_message : "")); +#else + error_code = errno; + LOG_ERROR("Error on socket '%s': errno==%d, message: %s.", socket_desc, error_code, strerror(error_code)); +#endif +} + +/** + * Find the first non-printable character in the char buffer, return a pointer to it. + * If no such character exists, return NULL. + */ +char *find_nonprint_char(char *buf, unsigned buf_len) +{ + for (unsigned int i = 0; i < buf_len; i++) { + if (!isprint(buf[i])) + return buf + i; } + return NULL; }