log.c 11.4 KB
Newer Older
1
2
3
4
/***************************************************************************
 *   Copyright (C) 2005 by Dominic Rath                                    *
 *   Dominic.Rath@gmx.de                                                   *
 *                                                                         *
5
 *   Copyright (C) 2007,2008 yvind Harboe                                 *
6
7
 *   oyvind.harboe@zylin.com                                               *
 *                                                                         *
8
9
10
 *   Copyright (C) 2008 by Spencer Oliver                                  *
 *   spen@spen-soft.co.uk                                                  *
 *                                                                         *
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
 *   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"
oharboe's avatar
oharboe committed
31
#include "time_support.h"
32
// @todo the inclusion of server.h here is a layering violation
33
#include "server.h"
34
35

#include <stdarg.h>
36

37
38
#ifdef _DEBUG_FREE_SPACE_
#ifdef HAVE_MALLOC_H
39
#include <malloc.h>
40
41
42
#else
#error "malloc.h is required to use --enable-malloc-logging"
#endif
43
#endif
44
45
46
47
48
49

int debug_level = -1;

static FILE* log_output;
static log_callback_t *log_callbacks = NULL;

50
51
52
static long long last_time;
static long long current_time;

53
static long long start;
54
55
56

static char *log_strings[5] =
{
57
58
59
60
61
	"User : ",
	"Error: ",
	"Warn : ",  /* want a space after each colon, all same width, colons aligned */
	"Info : ",
	"Debug: "
62
63
};

64

65
66
static int count = 0;

oharboe's avatar
oharboe committed
67
/* The log_puts() serves to somewhat different goals:
oharboe's avatar
   
oharboe committed
68
 *
69
70
 * - logging
 * - feeding low-level info to the user in GDB or Telnet
oharboe's avatar
   
oharboe committed
71
 *
72
 * The latter dictates that strings without newline are not logged, lest there
oharboe's avatar
   
oharboe committed
73
 * will be *MANY log lines when sending one char at the time(e.g.
74
 * target_request.c).
oharboe's avatar
   
oharboe committed
75
 *
76
 */
77
static void log_puts(enum log_levels level, const char *file, int line, const char *function, const char *string)
78
{
oharboe's avatar
oharboe committed
79
	char *f;
80
	if (level == LOG_LVL_OUTPUT)
81
82
	{
		/* do not prepend any headers, just print out what we were given and return */
83
		fputs(string, log_output);
84
85
86
87
		fflush(log_output);
		return;
	}

oharboe's avatar
oharboe committed
88
	f = strrchr(file, '/');
89
90
91
	if (f != NULL)
		file = f + 1;

zwelch's avatar
zwelch committed
92
	if (strchr(string, '\n') != NULL)
93
	{
94
		if (debug_level >= LOG_LVL_DEBUG)
95
96
		{
			/* print with count and time information */
97
			int t=(int)(timeval_ms()-start);
98
#ifdef _DEBUG_FREE_SPACE_
99
100
			struct mallinfo info;
			info = mallinfo();
101
#endif
102
			fprintf(log_output, "%s%d %d %s:%d %s()"
103
#ifdef _DEBUG_FREE_SPACE_
104
105
					" %d"
#endif
oharboe's avatar
   
oharboe committed
106
					": %s", log_strings[level+1], count, t, file, line, function,
107
#ifdef _DEBUG_FREE_SPACE_
108
109
110
					info.fordblks,
#endif
					string);
111
		}
zwelch's avatar
zwelch committed
112
		else if (server_use_pipes == 0)
113
		{
114
115
116
			/* 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)
117
118
119
120
121
			{
				/* print human readable output - but skip empty lines */
				fprintf(log_output, "%s%s",
						(level > LOG_LVL_USER)?log_strings[level+1]:"", string);
			}
122
123
		}
	} else
124
	{
oharboe's avatar
   
oharboe committed
125
		/* only entire lines are logged. Otherwise it's
126
		 * single chars intended for the log callbacks. */
127
128
129
	}

	fflush(log_output);
oharboe's avatar
   
oharboe committed
130

131
132
	/* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */
	if (level <= LOG_LVL_INFO)
133
	{
134
135
136
137
		log_callback_t *cb, *next;
		cb = log_callbacks;
		/* DANGER!!!! the log callback can remove itself!!!! */
		while (cb)
138
		{
139
			next=cb->next;
140
			cb->fn(cb->priv, file, line, function, string);
141
			cb=next;
142
143
144
145
		}
	}
}

146
147
void log_printf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
{
148
	char *string;
oharboe's avatar
oharboe committed
149
	va_list ap;
150

151
152
153
154
	count++;
	if (level > debug_level)
		return;

155
156
	va_start(ap, format);

oharboe's avatar
oharboe committed
157
	string = alloc_vprintf(format, ap);
158
159
160
161
162
	if (string != NULL)
	{
		log_puts(level, file, line, function, string);
		free(string);
	}
oharboe's avatar
   
oharboe committed
163

164
	va_end(ap);
165
166
}

167
void log_printf_lf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
168
{
169
	char *string;
oharboe's avatar
oharboe committed
170
	va_list ap;
171

172
173
174
	count++;
	if (level > debug_level)
		return;
oharboe's avatar
   
oharboe committed
175

176
	va_start(ap, format);
oharboe's avatar
   
oharboe committed
177

oharboe's avatar
oharboe committed
178
	string = alloc_vprintf(format, ap);
179
180
	if (string != NULL)
	{
oharboe's avatar
oharboe committed
181
		strcat(string, "\n"); /* alloc_vprintf guaranteed the buffer to be at least one char longer */
182
183
184
		log_puts(level, file, line, function, string);
		free(string);
	}
oharboe's avatar
   
oharboe committed
185

186
	va_end(ap);
187
188
}

189
190
191
192
193
194
195
196
/* 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)
{
197
198
199
200
201
202
203
204
205
206
	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;
207

208
209
210
211
212
213
214
215
216
217
218
	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");
		}
	}
219

220
221
	command_print(cmd_ctx, "debug_level: %i", debug_level);

222
223
224
225
226
227
228
229
	return ERROR_OK;
}

int handle_log_output_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc)
{
	if (argc == 1)
	{
		FILE* file = fopen(args[0], "w");
oharboe's avatar
   
oharboe committed
230

231
232
233
234
235
236
237
238
239
240
241
		if (file)
		{
			log_output = file;
		}
	}

	return ERROR_OK;
}

int log_register_commands(struct command_context_s *cmd_ctx)
{
242
	start = timeval_ms();
243
244
245
246
247
248
249
250
251
252
253
254
	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,
		COMMAND_ANY, "adjust debug level <0-3>");

	return ERROR_OK;
}

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)
255
		debug_level = LOG_LVL_INFO;
oharboe's avatar
   
oharboe committed
256

257
258
259
260
	if (log_output == NULL)
	{
		log_output = stderr;
	}
oharboe's avatar
   
oharboe committed
261

262
	start=last_time=timeval_ms();
oharboe's avatar
   
oharboe committed
263

264
265
	return ERROR_OK;
}
oharboe's avatar
   
oharboe committed
266

267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
int set_log_output(struct command_context_s *cmd_ctx, FILE *output)
{
	log_output = output;
	return ERROR_OK;
}

/* add/remove log callback handler */
int log_add_callback(log_callback_fn fn, void *priv)
{
	log_callback_t *cb;

	/* prevent the same callback to be registered more than once, just for sure */
	for (cb = log_callbacks; cb; cb = cb->next)
	{
		if (cb->fn == fn && cb->priv == priv)
			return ERROR_INVALID_ARGUMENTS;
	}

	/* 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)
		return ERROR_BUF_TOO_SMALL;

	/* add item to the beginning of the linked list */
	cb->fn = fn;
	cb->priv = priv;
	cb->next = log_callbacks;
	log_callbacks = cb;

	return ERROR_OK;
}

int log_remove_callback(log_callback_fn fn, void *priv)
{
	log_callback_t *cb, **p;

ntfreak's avatar
ntfreak committed
302
	for (p = &log_callbacks; (cb = *p); p = &(*p)->next)
303
	{
oharboe's avatar
oharboe committed
304
305
306
		if (cb->fn == fn && cb->priv == priv)
		{
			*p = cb->next;
307
308
309
310
311
312
313
314
315
316
			free(cb);
			return ERROR_OK;
		}
	}

	/* no such item */
	return ERROR_INVALID_ARGUMENTS;
}

/* return allocated string w/printf() result */
oharboe's avatar
oharboe committed
317
char *alloc_vprintf(const char *fmt, va_list ap)
318
{
319
	/* no buffer at the beginning, force realloc to do the job */
320
	char *string = NULL;
oharboe's avatar
   
oharboe committed
321

oharboe's avatar
oharboe committed
322
323
	/* start with buffer size suitable for typical messages */
	int size = 128;
324

325
326
	for (;;)
	{
oharboe's avatar
oharboe committed
327
		char *t = string;
oharboe's avatar
oharboe committed
328
329
		va_list ap_copy;
		int ret;
oharboe's avatar
oharboe committed
330
331
332
333
334
335
336
		string = realloc(string, size);
		if (string == NULL)
		{
			if (t != NULL)
				free(t);
			return NULL;
		}
337

oharboe's avatar
oharboe committed
338
		va_copy(ap_copy, ap);
339
340

		ret = vsnprintf(string, size, fmt, ap_copy);
oharboe's avatar
oharboe committed
341
342
		/* NB! The result of the vsnprintf() might be an *EMPTY* string! */
		if ((ret >= 0) && ((ret + 1) < size))
343
344
			break;

oharboe's avatar
oharboe committed
345
		/* there was just enough or not enough space, allocate more in the next round */
oharboe's avatar
oharboe committed
346
		size *= 2; /* double the buffer size */
347
	}
oharboe's avatar
   
oharboe committed
348

349
	/* the returned buffer is by principle guaranteed to be at least one character longer */
oharboe's avatar
oharboe committed
350
	return string;
351
}
oharboe's avatar
oharboe committed
352
353
354
355
356
357
358
359
360
361

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;
}
362
363
364

/* Code must return to the server loop before 1000ms has returned or invoke
 * this function.
oharboe's avatar
   
oharboe committed
365
 *
366
367
 * The GDB connection will time out if it spends >2000ms and you'll get nasty
 * error messages from GDB:
oharboe's avatar
   
oharboe committed
368
 *
369
370
371
372
373
374
375
 * 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.
oharboe's avatar
   
oharboe committed
376
 *
377
378
 * This function will send a keep alive packet if >500ms has passed since last time
 * it was invoked.
oharboe's avatar
   
oharboe committed
379
 *
380
381
 * Note that this function can be invoked often, so it needs to be relatively
 * fast when invoked more often than every 500ms.
oharboe's avatar
   
oharboe committed
382
 *
383
384
385
386
387
388
 */
void keep_alive()
{
	current_time=timeval_ms();
	if (current_time-last_time>1000)
	{
kc8apf's avatar
kc8apf committed
389
390
391
392
393
394
395
396
397
398
399
400
401
		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);
oharboe's avatar
   
oharboe committed
402
	}
403
	if (current_time-last_time>500)
404
405
406
	{
		/* this will keep the GDB connection alive */
		LOG_USER_N("%s", "");
407

oharboe's avatar
   
oharboe committed
408
409
410
411
412
413
414
		/* 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
		 */
415

416
417
418
419
420
421
422
423
424
425
		last_time=current_time;
	}
}

/* reset keep alive timer without sending message */
void kept_alive()
{
	current_time=timeval_ms();
	last_time=current_time;
}
426
427
428
429
430

/* if we sleep for extended periods of time, we must invoke keep_alive() intermittantly */
void alive_sleep(int ms)
{
	int i;
431
	int napTime=10;
zwelch's avatar
zwelch committed
432
	for (i=0; i<ms; i += napTime)
433
434
	{
		int sleep_a_bit=ms-i;
435
		if (sleep_a_bit>napTime)
436
		{
437
			sleep_a_bit=napTime;
438
439
440
441
442
		}
		usleep(sleep_a_bit*1000);
		keep_alive();
	}
}
443
444
445
446
447
448
449
450
451
452

void busy_sleep(int ms)
{
	long long then;
	then=timeval_ms();
	while ((timeval_ms()-then)<ms)
	{
		/* busy wait */
	}
}