- Fixed regression introduced in 890 when "fixing warnings" for target_call_timer_cal...
[fw/openocd] / src / helper / log.c
1 /***************************************************************************
2  *   Copyright (C) 2005 by Dominic Rath                                    *
3  *   Dominic.Rath@gmx.de                                                   *
4  *                                                                         *
5  *   Copyright (C) 2007,2008 Ã˜yvind Harboe                                      *
6  *   oyvind.harboe@zylin.com                                               *
7  *                                                                         *
8  *   This program is free software; you can redistribute it and/or modify  *
9  *   it under the terms of the GNU General Public License as published by  *
10  *   the Free Software Foundation; either version 2 of the License, or     *
11  *   (at your option) any later version.                                   *
12  *                                                                         *
13  *   This program is distributed in the hope that it will be useful,       *
14  *   but WITHOUT ANY WARRANTY; without even the implied warranty of        *
15  *   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the         *
16  *   GNU General Public License for more details.                          *
17  *                                                                         *
18  *   You should have received a copy of the GNU General Public License     *
19  *   along with this program; if not, write to the                         *
20  *   Free Software Foundation, Inc.,                                       *
21  *   59 Temple Place - Suite 330, Boston, MA  02111-1307, USA.             *
22  ***************************************************************************/
23 #ifdef HAVE_CONFIG_H
24 #include "config.h"
25 #endif
26
27 #include "log.h"
28 #include "configuration.h"
29 #include "time_support.h"
30 #include "command.h"
31
32 #include <stdio.h>
33 #include <stdlib.h>
34 #include <string.h>
35 #include <stdarg.h>
36
37 #define PRINT_MEM() 0
38 #if PRINT_MEM()
39 #include <malloc.h>
40 #endif
41
42 int debug_level = -1;
43
44 static FILE* log_output;
45 static log_callback_t *log_callbacks = NULL;
46
47 static long long last_time;
48 static long long current_time;
49
50 static long long start;
51
52 static char *log_strings[5] =
53 {
54         "User:   ",
55         "Error:  ",
56         "Warning:",
57         "Info:   ",
58         "Debug:  "
59 };
60
61 static int count = 0;
62
63 /* The log_puts() serves to somewhat different goals:
64  *
65  * - logging
66  * - feeding low-level info to the user in GDB or Telnet
67  *
68  * The latter dictates that strings without newline are not logged, lest there
69  * will be *MANY log lines when sending one char at the time(e.g.
70  * target_request.c).
71  *
72  */
73 static void log_puts(enum log_levels level, const char *file, int line, const char *function, const char *string)
74 {
75         char *f;
76         if (level == LOG_LVL_OUTPUT)
77         {
78                 /* do not prepend any headers, just print out what we were given and return */
79                 fputs(string, log_output);
80                 fflush(log_output);
81                 return;
82         }
83
84         f = strrchr(file, '/');
85         if (f != NULL)
86                 file = f + 1;
87
88         if (strchr(string, '\n')!=NULL)
89         {
90                 if (debug_level >= LOG_LVL_DEBUG)
91                 {
92                         /* print with count and time information */
93                         int t=(int)(timeval_ms()-start);
94 #if PRINT_MEM()
95                         struct mallinfo info;
96                         info = mallinfo();
97 #endif
98                         fprintf(log_output, "%s %d %d %s:%d %s()"
99 #if PRINT_MEM()
100                                         " %d"
101 #endif
102                                         ": %s", log_strings[level+1], count, t, file, line, function,
103 #if PRINT_MEM()
104                                         info.fordblks,
105 #endif
106                                         string);
107                 }
108                 else
109                 {
110                         if (strcmp(string, "\n")!=0)
111                         {
112                                 /* print human readable output - but skip empty lines */
113                                 fprintf(log_output, "%s%s",
114                                                 (level > LOG_LVL_USER)?log_strings[level+1]:"", string);
115                         }
116                 }
117         } else
118         {
119                 /* only entire lines are logged. Otherwise it's
120                  * single chars intended for the log callbacks. */
121         }
122
123         fflush(log_output);
124
125         /* Never forward LOG_LVL_DEBUG, too verbose and they can be found in the log if need be */
126         if (level <= LOG_LVL_INFO)
127         {
128                 log_callback_t *cb, *next;
129                 cb = log_callbacks;
130                 /* DANGER!!!! the log callback can remove itself!!!! */
131                 while (cb)
132                 {
133                         next=cb->next;
134                         cb->fn(cb->priv, file, line, function, string);
135                         cb=next;
136                 }
137         }
138 }
139
140 void log_printf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
141 {
142         char *string;
143         va_list ap;
144
145         count++;
146         if (level > debug_level)
147                 return;
148
149         va_start(ap, format);
150
151         string = alloc_vprintf(format, ap);
152         if (string != NULL)
153         {
154                 log_puts(level, file, line, function, string);
155                 free(string);
156         }
157
158         va_end(ap);
159 }
160
161 void log_printf_lf(enum log_levels level, const char *file, int line, const char *function, const char *format, ...)
162 {
163         char *string;
164         va_list ap;
165
166         count++;
167         if (level > debug_level)
168                 return;
169
170         va_start(ap, format);
171
172         string = alloc_vprintf(format, ap);
173         if (string != NULL)
174         {
175                 strcat(string, "\n"); /* alloc_vprintf guaranteed the buffer to be at least one char longer */
176                 log_puts(level, file, line, function, string);
177                 free(string);
178         }
179
180         va_end(ap);
181 }
182
183 /* change the current debug level on the fly
184  * 0: only ERRORS
185  * 1: + WARNINGS
186  * 2: + INFORMATIONAL MSGS
187  * 3: + DEBUG MSGS
188  */
189 int handle_debug_level_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc)
190 {
191         if (argc == 0)
192                 command_print(cmd_ctx, "debug_level: %i", debug_level);
193
194         if (argc > 0)
195                 debug_level = strtoul(args[0], NULL, 0);
196
197         if (debug_level < 0)
198                 debug_level = 0;
199
200         if (debug_level > 3)
201                 debug_level = 3;
202
203         return ERROR_OK;
204 }
205
206 int handle_log_output_command(struct command_context_s *cmd_ctx, char *cmd, char **args, int argc)
207 {
208         if (argc == 1)
209         {
210                 FILE* file = fopen(args[0], "w");
211
212                 if (file)
213                 {
214                         log_output = file;
215                 }
216         }
217
218         return ERROR_OK;
219 }
220
221 int log_register_commands(struct command_context_s *cmd_ctx)
222 {
223         start = timeval_ms();
224         register_command(cmd_ctx, NULL, "log_output", handle_log_output_command,
225                 COMMAND_ANY, "redirect logging to <file> (default: stderr)");
226         register_command(cmd_ctx, NULL, "debug_level", handle_debug_level_command,
227                 COMMAND_ANY, "adjust debug level <0-3>");
228
229         return ERROR_OK;
230 }
231
232 int log_init(struct command_context_s *cmd_ctx)
233 {
234         /* set defaults for daemon configuration, if not set by cmdline or cfgfile */
235         if (debug_level == -1)
236                 debug_level = LOG_LVL_INFO;
237
238         if (log_output == NULL)
239         {
240                 log_output = stderr;
241         }
242
243         start=last_time=timeval_ms();
244
245         return ERROR_OK;
246 }
247
248 int set_log_output(struct command_context_s *cmd_ctx, FILE *output)
249 {
250         log_output = output;
251         return ERROR_OK;
252 }
253
254 /* add/remove log callback handler */
255 int log_add_callback(log_callback_fn fn, void *priv)
256 {
257         log_callback_t *cb;
258
259         /* prevent the same callback to be registered more than once, just for sure */
260         for (cb = log_callbacks; cb; cb = cb->next)
261         {
262                 if (cb->fn == fn && cb->priv == priv)
263                         return ERROR_INVALID_ARGUMENTS;
264         }
265
266         /* alloc memory, it is safe just to return in case of an error, no need for the caller to check this */
267         if ((cb = malloc(sizeof(log_callback_t))) == NULL)
268                 return ERROR_BUF_TOO_SMALL;
269
270         /* add item to the beginning of the linked list */
271         cb->fn = fn;
272         cb->priv = priv;
273         cb->next = log_callbacks;
274         log_callbacks = cb;
275
276         return ERROR_OK;
277 }
278
279 int log_remove_callback(log_callback_fn fn, void *priv)
280 {
281         log_callback_t *cb, **p;
282
283         for (p = &log_callbacks; (cb = *p); p = &(*p)->next)
284         {
285                 if (cb->fn == fn && cb->priv == priv)
286                 {
287                         *p = cb->next;
288                         free(cb);
289                         return ERROR_OK;
290                 }
291         }
292
293         /* no such item */
294         return ERROR_INVALID_ARGUMENTS;
295 }
296
297 /* return allocated string w/printf() result */
298 char *alloc_vprintf(const char *fmt, va_list ap)
299 {
300         /* no buffer at the beginning, force realloc to do the job */
301         char *string = NULL;
302
303         /* start with buffer size suitable for typical messages */
304         int size = 128;
305
306         for (;;)
307         {
308                 char *t = string;
309                 va_list ap_copy;
310                 int ret;
311                 string = realloc(string, size);
312                 if (string == NULL)
313                 {
314                         if (t != NULL)
315                                 free(t);
316                         return NULL;
317                 }
318
319                 va_copy(ap_copy, ap);
320
321                 ret = vsnprintf(string, size, fmt, ap_copy);
322                 /* NB! The result of the vsnprintf() might be an *EMPTY* string! */
323                 if ((ret >= 0) && ((ret + 1) < size))
324                         break;
325
326                 /* there was just enough or not enough space, allocate more in the next round */
327                 size *= 2; /* double the buffer size */
328         }
329
330         /* the returned buffer is by principle guaranteed to be at least one character longer */
331         return string;
332 }
333
334 char *alloc_printf(const char *format, ...)
335 {
336         char *string;
337         va_list ap;
338         va_start(ap, format);
339         string = alloc_vprintf(format, ap);
340         va_end(ap);
341         return string;
342 }
343
344 /* Code must return to the server loop before 1000ms has returned or invoke
345  * this function.
346  *
347  * The GDB connection will time out if it spends >2000ms and you'll get nasty
348  * error messages from GDB:
349  *
350  * Ignoring packet error, continuing...
351  * Reply contains invalid hex digit 116
352  *
353  * While it is possible use "set remotetimeout" to more than the default 2000ms
354  * in GDB, OpenOCD guarantees that it sends keep-alive packages on the
355  * GDB protocol and it is a bug in OpenOCD not to either return to the server
356  * loop or invoke keep_alive() every 1000ms.
357  *
358  * This function will send a keep alive packet if >500ms has passed since last time
359  * it was invoked.
360  *
361  * Note that this function can be invoked often, so it needs to be relatively
362  * fast when invoked more often than every 500ms.
363  *
364  */
365 void keep_alive()
366 {
367         current_time=timeval_ms();
368         if (current_time-last_time>1000)
369         {
370                 LOG_WARNING("BUG: keep_alive() was not invoked in the 1000ms timelimit. GDB alive packet not sent! (%lld)", current_time-last_time);
371         }
372         if (current_time-last_time>500)
373         {
374                 /* this will keep the GDB connection alive */
375                 LOG_USER_N("%s", "");
376
377                 /* DANGER!!!! do not add code to invoke e.g. target event processing,
378                  * jim timer processing, etc. it can cause infinite recursion +
379                  * jim event callbacks need to happen at a well defined time,
380                  * not anywhere keep_alive() is invoked.
381                  *
382                  * These functions should be invoked at a well defined spot in server.c
383                  */
384
385                 last_time=current_time;
386         }
387 }
388
389 /* reset keep alive timer without sending message */
390 void kept_alive()
391 {
392         current_time=timeval_ms();
393         last_time=current_time;
394 }
395
396 /* if we sleep for extended periods of time, we must invoke keep_alive() intermittantly */
397 void alive_sleep(int ms)
398 {
399         int i;
400         for (i=0; i<ms; i+=500)
401         {
402                 int sleep_a_bit=ms-i;
403                 if (sleep_a_bit>500)
404                 {
405                         sleep_a_bit=500;
406                 }
407                 keep_alive();
408                 usleep(sleep_a_bit*1000);
409                 keep_alive();
410         }
411 }