OpenOCD
log.c
Go to the documentation of this file.
1 // SPDX-License-Identifier: GPL-2.0-or-later
2 
3 /***************************************************************************
4  * Copyright (C) 2005 by Dominic Rath *
5  * Dominic.Rath@gmx.de *
6  * *
7  * Copyright (C) 2007-2010 Øyvind Harboe *
8  * oyvind.harboe@zylin.com *
9  * *
10  * Copyright (C) 2008 by Spencer Oliver *
11  * spen@spen-soft.co.uk *
12  ***************************************************************************/
13 
14 #ifdef HAVE_CONFIG_H
15 #include "config.h"
16 #endif
17 
18 #include "log.h"
19 #include "command.h"
20 #include "replacements.h"
21 #include "time_support.h"
22 #include <server/server.h>
23 
24 #include <stdarg.h>
25 
26 #ifdef _DEBUG_FREE_SPACE_
27 #ifdef HAVE_MALLOC_H
28 #include <malloc.h>
29 #else
30 #error "malloc.h is required to use --enable-malloc-logging"
31 #endif
32 #endif
33 
35 
36 static FILE *log_output;
37 static struct log_callback *log_callbacks;
38 
39 static int64_t last_time;
40 
41 static int64_t start;
42 
43 static const char * const log_strings[6] = {
44  "User : ",
45  "Error: ",
46  "Warn : ", /* want a space after each colon, all same width, colons aligned */
47  "Info : ",
48  "Debug: ",
49  "Debug: "
50 };
51 
52 static int count;
53 
54 /* forward the log to the listeners */
55 static void log_forward(const char *file, unsigned line, const char *function, const char *string)
56 {
57  struct log_callback *cb, *next;
58  cb = log_callbacks;
59  /* DANGER!!!! the log callback can remove itself!!!! */
60  while (cb) {
61  next = cb->next;
62  cb->fn(cb->priv, file, line, function, string);
63  cb = next;
64  }
65 }
66 
67 /* The log_puts() serves two somewhat different goals:
68  *
69  * - logging
70  * - feeding low-level info to the user in GDB or Telnet
71  *
72  * The latter dictates that strings without newline are not logged, lest there
73  * will be *MANY log lines when sending one char at the time(e.g.
74  * target_request.c).
75  *
76  */
77 static void log_puts(enum log_levels level,
78  const char *file,
79  int line,
80  const char *function,
81  const char *string)
82 {
83  char *f;
84 
85  if (!log_output) {
86  /* log_init() not called yet; print on stderr */
87  fputs(string, stderr);
88  fflush(stderr);
89  return;
90  }
91 
92  if (level == LOG_LVL_OUTPUT) {
93  /* do not prepend any headers, just print out what we were given and return */
94  fputs(string, log_output);
95  fflush(log_output);
96  return;
97  }
98 
99  f = strrchr(file, '/');
100  if (f)
101  file = f + 1;
102 
103  if (debug_level >= LOG_LVL_DEBUG) {
104  /* print with count and time information */
105  int64_t t = timeval_ms() - start;
106 #ifdef _DEBUG_FREE_SPACE_
107  struct mallinfo info;
108  info = mallinfo();
109 #endif
110  fprintf(log_output, "%s%d %" PRId64 " %s:%d %s()"
111 #ifdef _DEBUG_FREE_SPACE_
112  " %d"
113 #endif
114  ": %s", log_strings[level + 1], count, t, file, line, function,
115 #ifdef _DEBUG_FREE_SPACE_
116  info.fordblks,
117 #endif
118  string);
119  } else {
120  /* if we are using gdb through pipes then we do not want any output
121  * to the pipe otherwise we get repeated strings */
122  fprintf(log_output, "%s%s",
123  (level > LOG_LVL_USER) ? log_strings[level + 1] : "", string);
124  }
125 
126  fflush(log_output);
127 
128  /* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */
129  if (level <= LOG_LVL_INFO)
130  log_forward(file, line, function, string);
131 }
132 
133 void log_printf(enum log_levels level,
134  const char *file,
135  unsigned line,
136  const char *function,
137  const char *format,
138  ...)
139 {
140  char *string;
141  va_list ap;
142 
143  count++;
144  if (level > debug_level)
145  return;
146 
147  va_start(ap, format);
148 
149  string = alloc_vprintf(format, ap);
150  if (string) {
151  log_puts(level, file, line, function, string);
152  free(string);
153  }
154 
155  va_end(ap);
156 }
157 
158 void log_vprintf_lf(enum log_levels level, const char *file, unsigned line,
159  const char *function, const char *format, va_list args)
160 {
161  char *tmp;
162 
163  count++;
164 
165  if (level > debug_level)
166  return;
167 
168  tmp = alloc_vprintf(format, args);
169 
170  if (!tmp)
171  return;
172 
173  /*
174  * Note: alloc_vprintf() guarantees that the buffer is at least one
175  * character longer.
176  */
177  strcat(tmp, "\n");
178  log_puts(level, file, line, function, tmp);
179  free(tmp);
180 }
181 
182 void log_printf_lf(enum log_levels level,
183  const char *file,
184  unsigned line,
185  const char *function,
186  const char *format,
187  ...)
188 {
189  va_list ap;
190 
191  va_start(ap, format);
192  log_vprintf_lf(level, file, line, function, format, ap);
193  va_end(ap);
194 }
195 
196 COMMAND_HANDLER(handle_debug_level_command)
197 {
198  if (CMD_ARGC == 1) {
199  int new_level;
200  COMMAND_PARSE_NUMBER(int, CMD_ARGV[0], new_level);
201  if ((new_level > LOG_LVL_DEBUG_IO) || (new_level < LOG_LVL_SILENT)) {
202  LOG_ERROR("level must be between %d and %d", LOG_LVL_SILENT, LOG_LVL_DEBUG_IO);
204  }
205  debug_level = new_level;
206  } else if (CMD_ARGC > 1)
208 
209  command_print(CMD, "debug_level: %i", debug_level);
210 
211  return ERROR_OK;
212 }
213 
214 COMMAND_HANDLER(handle_log_output_command)
215 {
216  if (CMD_ARGC == 0 || (CMD_ARGC == 1 && strcmp(CMD_ARGV[0], "default") == 0)) {
217  if (log_output != stderr && log_output) {
218  /* Close previous log file, if it was open and wasn't stderr. */
219  fclose(log_output);
220  }
221  log_output = stderr;
222  LOG_DEBUG("set log_output to default");
223  return ERROR_OK;
224  }
225  if (CMD_ARGC == 1) {
226  FILE *file = fopen(CMD_ARGV[0], "w");
227  if (!file) {
228  LOG_ERROR("failed to open output log '%s'", CMD_ARGV[0]);
229  return ERROR_FAIL;
230  }
231  if (log_output != stderr && log_output) {
232  /* Close previous log file, if it was open and wasn't stderr. */
233  fclose(log_output);
234  }
235  log_output = file;
236  LOG_DEBUG("set log_output to \"%s\"", CMD_ARGV[0]);
237  return ERROR_OK;
238  }
239 
241 }
242 
243 static const struct command_registration log_command_handlers[] = {
244  {
245  .name = "log_output",
246  .handler = handle_log_output_command,
247  .mode = COMMAND_ANY,
248  .help = "redirect logging to a file (default: stderr)",
249  .usage = "[file_name | \"default\"]",
250  },
251  {
252  .name = "debug_level",
253  .handler = handle_debug_level_command,
254  .mode = COMMAND_ANY,
255  .help = "Sets the verbosity level of debugging output. "
256  "0 shows errors only; 1 adds warnings; "
257  "2 (default) adds other info; 3 adds debugging; "
258  "4 adds extra verbose debugging.",
259  .usage = "number",
260  },
262 };
263 
265 {
266  return register_commands(cmd_ctx, NULL, log_command_handlers);
267 }
268 
269 void log_init(void)
270 {
271  /* set defaults for daemon configuration,
272  * if not set by cmdline or cfgfile */
273  char *debug_env = getenv("OPENOCD_DEBUG_LEVEL");
274  if (debug_env) {
275  int value;
276  int retval = parse_int(debug_env, &value);
277  if (retval == ERROR_OK &&
280  debug_level = value;
281  }
282 
283  if (!log_output)
284  log_output = stderr;
285 
286  start = last_time = timeval_ms();
287 }
288 
289 void log_exit(void)
290 {
291  if (log_output && log_output != stderr) {
292  /* Close log file, if it was open and wasn't stderr. */
293  fclose(log_output);
294  }
295  log_output = NULL;
296 }
297 
298 /* add/remove log callback handler */
300 {
301  struct log_callback *cb;
302 
303  /* prevent the same callback to be registered more than once, just for sure */
304  for (cb = log_callbacks; cb; cb = cb->next) {
305  if (cb->fn == fn && cb->priv == priv)
307  }
308 
309  /* alloc memory, it is safe just to return in case of an error, no need for the caller to
310  *check this */
311  cb = malloc(sizeof(struct log_callback));
312  if (!cb)
313  return ERROR_BUF_TOO_SMALL;
314 
315  /* add item to the beginning of the linked list */
316  cb->fn = fn;
317  cb->priv = priv;
318  cb->next = log_callbacks;
319  log_callbacks = cb;
320 
321  return ERROR_OK;
322 }
323 
325 {
326  struct log_callback *cb, **p;
327 
328  for (p = &log_callbacks; (cb = *p); p = &(*p)->next) {
329  if (cb->fn == fn && cb->priv == priv) {
330  *p = cb->next;
331  free(cb);
332  return ERROR_OK;
333  }
334  }
335 
336  /* no such item */
338 }
339 
340 /* return allocated string w/printf() result */
341 char *alloc_vprintf(const char *fmt, va_list ap)
342 {
343  va_list ap_copy;
344  int len;
345  char *string;
346 
347  /* determine the length of the buffer needed */
348  va_copy(ap_copy, ap);
349  len = vsnprintf(NULL, 0, fmt, ap_copy);
350  va_end(ap_copy);
351 
352  /* allocate and make room for terminating zero. */
353  /* FIXME: The old version always allocated at least one byte extra and
354  * other code depend on that. They should be probably be fixed, but for
355  * now reserve the extra byte. */
356  string = malloc(len + 2);
357  if (!string)
358  return NULL;
359 
360  /* do the real work */
361  vsnprintf(string, len + 1, fmt, ap);
362 
363  return string;
364 }
365 
366 char *alloc_printf(const char *format, ...)
367 {
368  char *string;
369  va_list ap;
370  va_start(ap, format);
371  string = alloc_vprintf(format, ap);
372  va_end(ap);
373  return string;
374 }
375 
376 /* Code must return to the server loop before 1000ms has returned or invoke
377  * this function.
378  *
379  * The GDB connection will time out if it spends >2000ms and you'll get nasty
380  * error messages from GDB:
381  *
382  * Ignoring packet error, continuing...
383  * Reply contains invalid hex digit 116
384  *
385  * While it is possible use "set remotetimeout" to more than the default 2000ms
386  * in GDB, OpenOCD guarantees that it sends keep-alive packages on the
387  * GDB protocol and it is a bug in OpenOCD not to either return to the server
388  * loop or invoke keep_alive() every 1000ms.
389  *
390  * This function will send a keep alive packet if >500ms has passed since last time
391  * it was invoked.
392  *
393  * Note that this function can be invoked often, so it needs to be relatively
394  * fast when invoked more often than every 500ms.
395  *
396  */
397 #define KEEP_ALIVE_KICK_TIME_MS 500
398 #define KEEP_ALIVE_TIMEOUT_MS 1000
399 
400 static void gdb_timeout_warning(int64_t delta_time)
401 {
402  extern int gdb_actual_connections;
403 
405  LOG_WARNING("keep_alive() was not invoked in the "
406  "%d ms timelimit. GDB alive packet not "
407  "sent! (%" PRId64 " ms). Workaround: increase "
408  "\"set remotetimeout\" in GDB",
410  delta_time);
411  else
412  LOG_DEBUG("keep_alive() was not invoked in the "
413  "%d ms timelimit (%" PRId64 " ms). This may cause "
414  "trouble with GDB connections.",
416  delta_time);
417 }
418 
419 void keep_alive(void)
420 {
421  int64_t current_time = timeval_ms();
422  int64_t delta_time = current_time - last_time;
423 
424  if (delta_time > KEEP_ALIVE_TIMEOUT_MS) {
425  last_time = current_time;
426 
427  gdb_timeout_warning(delta_time);
428  }
429 
430  if (delta_time > KEEP_ALIVE_KICK_TIME_MS) {
431  last_time = current_time;
432 
433  /* this will keep the GDB connection alive */
435 
436  /* DANGER!!!! do not add code to invoke e.g. target event processing,
437  * jim timer processing, etc. it can cause infinite recursion +
438  * jim event callbacks need to happen at a well defined time,
439  * not anywhere keep_alive() is invoked.
440  *
441  * These functions should be invoked at a well defined spot in server.c
442  */
443  }
444 }
445 
446 /* reset keep alive timer without sending message */
447 void kept_alive(void)
448 {
449  int64_t current_time = timeval_ms();
450 
451  int64_t delta_time = current_time - last_time;
452 
453  last_time = current_time;
454 
455  if (delta_time > KEEP_ALIVE_TIMEOUT_MS)
456  gdb_timeout_warning(delta_time);
457 }
458 
459 /* if we sleep for extended periods of time, we must invoke keep_alive() intermittently */
460 void alive_sleep(uint64_t ms)
461 {
462  uint64_t nap_time = 10;
463  for (uint64_t i = 0; i < ms; i += nap_time) {
464  uint64_t sleep_a_bit = ms - i;
465  if (sleep_a_bit > nap_time)
466  sleep_a_bit = nap_time;
467 
468  usleep(sleep_a_bit * 1000);
469  keep_alive();
470  }
471 }
472 
473 void busy_sleep(uint64_t ms)
474 {
475  uint64_t then = timeval_ms();
476  while (timeval_ms() - then < ms) {
477  /*
478  * busy wait
479  */
480  }
481 }
482 
483 /* Maximum size of socket error message retrieved from operation system */
484 #define MAX_SOCKET_ERR_MSG_LENGTH 256
485 
486 /* Provide log message for the last socket error.
487  Uses errno on *nix and WSAGetLastError() on Windows */
488 void log_socket_error(const char *socket_desc)
489 {
490  int error_code;
491 #ifdef _WIN32
492  error_code = WSAGetLastError();
493  char error_message[MAX_SOCKET_ERR_MSG_LENGTH];
494  error_message[0] = '\0';
495  DWORD retval = FormatMessage(FORMAT_MESSAGE_FROM_SYSTEM, NULL, error_code, 0,
496  error_message, MAX_SOCKET_ERR_MSG_LENGTH, NULL);
497  error_message[MAX_SOCKET_ERR_MSG_LENGTH - 1] = '\0';
498  const bool have_message = (retval != 0) && (error_message[0] != '\0');
499  LOG_ERROR("Error on socket '%s': WSAGetLastError==%d%s%s.", socket_desc, error_code,
500  (have_message ? ", message: " : ""),
501  (have_message ? error_message : ""));
502 #else
503  error_code = errno;
504  LOG_ERROR("Error on socket '%s': errno==%d, message: %s.", socket_desc, error_code, strerror(error_code));
505 #endif
506 }
507 
512 char *find_nonprint_char(char *buf, unsigned buf_len)
513 {
514  for (unsigned int i = 0; i < buf_len; i++) {
515  if (!isprint(buf[i]))
516  return buf + i;
517  }
518  return NULL;
519 }
void command_print(struct command_invocation *cmd, const char *format,...)
Definition: command.c:473
#define CMD
Use this macro to access the command being handled, rather than accessing the variable directly.
Definition: command.h:140
#define CMD_ARGV
Use this macro to access the arguments for the command being handled, rather than accessing the varia...
Definition: command.h:155
#define ERROR_COMMAND_SYNTAX_ERROR
Definition: command.h:385
#define CMD_ARGC
Use this macro to access the number of arguments for the command being handled, rather than accessing...
Definition: command.h:150
#define COMMAND_PARSE_NUMBER(type, in, out)
parses the string in into out as a type, or prints a command error and passes the error code to the c...
Definition: command.h:425
#define COMMAND_REGISTRATION_DONE
Use this as the last entry in an array of command_registration records.
Definition: command.h:247
static int register_commands(struct command_context *cmd_ctx, const char *cmd_prefix, const struct command_registration *cmds)
Register one or more commands in the specified context, as children of parent (or top-level commends,...
Definition: command.h:268
@ COMMAND_ANY
Definition: command.h:42
static struct esp_usb_jtag * priv
Definition: esp_usb_jtag.c:219
int gdb_actual_connections
Definition: gdb_server.c:120
int log_remove_callback(log_callback_fn fn, void *priv)
Definition: log.c:324
void log_printf(enum log_levels level, const char *file, unsigned line, const char *function, const char *format,...)
Definition: log.c:133
void log_printf_lf(enum log_levels level, const char *file, unsigned line, const char *function, const char *format,...)
Definition: log.c:182
int log_register_commands(struct command_context *cmd_ctx)
Definition: log.c:264
void log_init(void)
Initialize logging module.
Definition: log.c:269
int log_add_callback(log_callback_fn fn, void *priv)
Definition: log.c:299
static const struct command_registration log_command_handlers[]
Definition: log.c:243
char * alloc_vprintf(const char *fmt, va_list ap)
Definition: log.c:341
static void gdb_timeout_warning(int64_t delta_time)
Definition: log.c:400
char * find_nonprint_char(char *buf, unsigned buf_len)
Find the first non-printable character in the char buffer, return a pointer to it.
Definition: log.c:512
int debug_level
Definition: log.c:34
void alive_sleep(uint64_t ms)
Definition: log.c:460
void busy_sleep(uint64_t ms)
Definition: log.c:473
static struct log_callback * log_callbacks
Definition: log.c:37
void log_vprintf_lf(enum log_levels level, const char *file, unsigned line, const char *function, const char *format, va_list args)
Definition: log.c:158
void keep_alive(void)
Definition: log.c:419
static int64_t start
Definition: log.c:41
COMMAND_HANDLER(handle_debug_level_command)
Definition: log.c:196
static FILE * log_output
Definition: log.c:36
void log_socket_error(const char *socket_desc)
Definition: log.c:488
void log_exit(void)
Definition: log.c:289
#define MAX_SOCKET_ERR_MSG_LENGTH
Definition: log.c:484
#define KEEP_ALIVE_TIMEOUT_MS
Definition: log.c:398
void kept_alive(void)
Definition: log.c:447
static int count
Definition: log.c:52
#define KEEP_ALIVE_KICK_TIME_MS
Definition: log.c:397
static int64_t last_time
Definition: log.c:39
char * alloc_printf(const char *format,...)
Definition: log.c:366
static void log_puts(enum log_levels level, const char *file, int line, const char *function, const char *string)
Definition: log.c:77
static const char *const log_strings[6]
Definition: log.c:43
static void log_forward(const char *file, unsigned line, const char *function, const char *string)
Definition: log.c:55
#define LOG_WARNING(expr ...)
Definition: log.h:120
#define ERROR_FAIL
Definition: log.h:161
#define ERROR_BUF_TOO_SMALL
Definition: log.h:157
#define LOG_ERROR(expr ...)
Definition: log.h:123
#define LOG_DEBUG(expr ...)
Definition: log.h:109
void(* log_callback_fn)(void *priv, const char *file, unsigned line, const char *function, const char *string)
Definition: log.h:76
#define ERROR_OK
Definition: log.h:155
log_levels
Definition: log.h:40
@ LOG_LVL_OUTPUT
Definition: log.h:42
@ LOG_LVL_INFO
Definition: log.h:46
@ LOG_LVL_USER
Definition: log.h:43
@ LOG_LVL_DEBUG
Definition: log.h:47
@ LOG_LVL_DEBUG_IO
Definition: log.h:48
@ LOG_LVL_SILENT
Definition: log.h:41
void server_keep_clients_alive(void)
Definition: server.c:413
const char * name
Definition: command.h:229
struct log_callback * next
Definition: log.h:82
void * priv
Definition: log.h:81
log_callback_fn fn
Definition: log.h:80
int64_t timeval_ms(void)
static struct ublast_lowlevel_priv info
#define NULL
Definition: usb.h:16
#define DWORD
Definition: x86_32_common.h:33