X-Git-Url: https://git.gag.com/?a=blobdiff_plain;f=src%2Fhelper%2Flog.c;h=106d228675d012a08a4bc71ebeced21fbfc63ab9;hb=96202cda1906be3b698614a6a7977cc5e6407cf6;hp=79cbd8ec89a16d8c6f86185b6018abe12fa6281c;hpb=f19ac83152b54a204b8148815a538d868973e1e1;p=fw%2Fopenocd diff --git a/src/helper/log.c b/src/helper/log.c index 79cbd8ec8..106d22867 100644 --- a/src/helper/log.c +++ b/src/helper/log.c @@ -28,7 +28,9 @@ #include "log.h" #include "command.h" +#include "replacements.h" #include "time_support.h" +#include #include @@ -40,70 +42,40 @@ #endif #endif -int debug_level = -1; +int debug_level = LOG_LVL_INFO; static FILE *log_output; static struct log_callback *log_callbacks; static int64_t last_time; -static int64_t current_time; static int64_t start; -static const char * const log_strings[5] = { +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; -static struct store_log_forward *log_head; -static int log_forward_count; - -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 @@ -120,6 +92,14 @@ static void log_puts(enum log_levels level, const char *string) { char *f; + + 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); @@ -128,35 +108,30 @@ static void log_puts(enum log_levels level, } 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 */ - int64_t t = 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 %" PRId64 " %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); - } + string); } else { - /* Empty strings are sent to log callbacks to keep e.g. gdbserver alive, here we do - *nothing. */ + /* 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); @@ -183,7 +158,7 @@ void log_printf(enum log_levels level, va_start(ap, format); string = alloc_vprintf(format, ap); - if (string != NULL) { + if (string) { log_puts(level, file, line, function, string); free(string); } @@ -191,6 +166,30 @@ void log_printf(enum log_levels level, va_end(ap); } +void log_vprintf_lf(enum log_levels level, const char *file, unsigned line, + const char *function, const char *format, va_list args) +{ + 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, @@ -198,23 +197,10 @@ void log_printf_lf(enum log_levels level, const char *format, ...) { - char *string; va_list ap; - count++; - if (level > debug_level) - return; - va_start(ap, format); - - 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); - } - + log_vprintf_lf(level, file, line, function, format, ap); va_end(ap); } @@ -223,38 +209,55 @@ COMMAND_HANDLER(handle_debug_level_command) if (CMD_ARGC == 1) { int new_level; COMMAND_PARSE_NUMBER(int, CMD_ARGV[0], new_level); - if ((new_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) 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 == 0 || (CMD_ARGC == 1 && strcmp(CMD_ARGV[0], "default") == 0)) { + if (log_output != stderr && log_output) { + /* Close previous log file, if it was open and wasn't stderr. */ + fclose(log_output); + } + log_output = stderr; + LOG_DEBUG("set log_output to default"); + return ERROR_OK; + } if (CMD_ARGC == 1) { FILE *file = fopen(CMD_ARGV[0], "w"); - - if (file) - log_output = file; + if (!file) { + LOG_ERROR("failed to open output log '%s'", CMD_ARGV[0]); + return ERROR_FAIL; + } + if (log_output != stderr && log_output) { + /* Close previous log file, if it was open and wasn't stderr. */ + fclose(log_output); + } + log_output = file; + LOG_DEBUG("set log_output to \"%s\"", CMD_ARGV[0]); + return ERROR_OK; } - return ERROR_OK; + return ERROR_COMMAND_SYNTAX_ERROR; } -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", @@ -262,7 +265,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 @@ -277,25 +281,31 @@ 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 <= LOG_LVL_DEBUG_IO) debug_level = value; } - if (log_output == NULL) + if (!log_output) log_output = stderr; start = last_time = timeval_ms(); } +void log_exit(void) +{ + if (log_output && log_output != stderr) { + /* Close log file, if it was open and wasn't stderr. */ + fclose(log_output); + } + log_output = NULL; +} + int set_log_output(struct command_context *cmd_ctx, FILE *output) { log_output = output; @@ -316,7 +326,7 @@ int log_add_callback(log_callback_fn fn, void *priv) /* 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) + if (!cb) return ERROR_BUF_TOO_SMALL; /* add item to the beginning of the linked list */ @@ -361,7 +371,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 */ @@ -401,27 +411,44 @@ 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) +{ + extern int gdb_actual_connections; + + if (gdb_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) { - 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); + 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 + @@ -430,26 +457,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(); @@ -465,3 +496,41 @@ void busy_sleep(uint64_t ms) */ } } + +/* 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; +}