1 /*******************************************************************************
2 * Copyright (c) 2009, 2022 IBM Corp.
3 *
4 * All rights reserved. This program and the accompanying materials
5 * are made available under the terms of the Eclipse Public License v2.0
6 * and Eclipse Distribution License v1.0 which accompany this distribution.
7 *
8 * The Eclipse Public License is available at
9 * https://www.eclipse.org/legal/epl-2.0/
10 * and the Eclipse Distribution License is available at
11 * http://www.eclipse.org/org/documents/edl-v10.php.
12 *
13 * Contributors:
14 * Ian Craggs - initial API and implementation and/or initial documentation
15 * Ian Craggs - updates for the async client
16 * Ian Craggs - fix for bug #427028
17 *******************************************************************************/
18
19 /**
20 * @file
21 * \brief Logging and tracing module
22 *
23 *
24 */
25
26 #include "Log.h"
27 #include "MQTTPacket.h"
28 #include "MQTTProtocol.h"
29 #include "MQTTProtocolClient.h"
30 #include "Messages.h"
31 #include "LinkedList.h"
32 #include "StackTrace.h"
33 #include "Thread.h"
34
35 #include <stdio.h>
36 #include <stdlib.h>
37 #include <stdarg.h>
38 #include <time.h>
39 #include <string.h>
40
41 #if !defined(_WIN32) && !defined(_WIN64)
42 #if !defined(IOT_CONNECT) && !defined(IOT_LITEOS_ADAPT)
43 #include <syslog.h>
44 #include <sys/stat.h>
45 #endif
46 #define GETTIMEOFDAY 1
47 #else
48 #define snprintf _snprintf
49 #endif
50
51 #if defined(GETTIMEOFDAY)
52 #include <sys/time.h>
53 #else
54 #include <sys/timeb.h>
55 #endif
56
57 #if defined(IOT_CONNECT)
58 #include "atiny_mqtt_commu.h"
59 #endif
60
61 #if !defined(_WIN32) && !defined(_WIN64) && !defined(IOT_CONNECT)
62 /**
63 * _unlink mapping for linux
64 */
65 #define _unlink unlink
66 #endif
67
68
69 #if !defined(min)
70 #define min(A,B) ( (A) < (B) ? (A):(B))
71 #endif
72 #if defined(IOT_LITEOS_ADAPT)
73 #include "osal_debug.h"
74 #endif
75 #if defined(IOT_CONNECT) || defined(IOT_LITEOS_ADAPT)
76 trace_settings_type trace_settings =
77 {
78 TRACE_MINIMUM,
79 5,
80 INVALID_LEVEL
81 };
82 #else
83 trace_settings_type trace_settings =
84 {
85 #if defined(HIGH_PERFORMANCE)
86 LOG_ERROR,
87 #else
88 TRACE_MINIMUM,
89 #endif
90 400,
91 INVALID_LEVEL
92 };
93 #endif
94
95 #define MAX_FUNCTION_NAME_LENGTH 256
96
97 typedef struct
98 {
99 #if defined(GETTIMEOFDAY)
100 struct timeval ts;
101 #else
102 struct timeb ts;
103 #endif
104 int sametime_count;
105 int number;
106 thread_id_type thread_id;
107 int depth;
108 char name[MAX_FUNCTION_NAME_LENGTH + 1];
109 int line;
110 int has_rc;
111 int rc;
112 enum LOG_LEVELS level;
113 } traceEntry;
114
115 static int start_index = -1,
116 next_index = 0;
117 static traceEntry* trace_queue = NULL;
118 static int trace_queue_size = 0;
119
120 #if !defined (IOT_CONNECT) && !defined(IOT_LITEOS_ADAPT)
121 static FILE* trace_destination = NULL; /**< flag to indicate if trace is to be sent to a stream */
122 static char* trace_destination_name = NULL; /**< the name of the trace file */
123 static char* trace_destination_backup_name = NULL; /**< the name of the backup trace file */
124 static int lines_written = 0; /**< number of lines written to the current output file */
125 static int max_lines_per_file = 1000; /**< maximum number of lines to write to one trace file */
126 #endif
127 static enum LOG_LEVELS trace_output_level = INVALID_LEVEL;
128 static Log_traceCallback* trace_callback = NULL;
129 static traceEntry* Log_pretrace(void);
130 #if !defined (IOT_CONNECT) && !defined(IOT_LITEOS_ADAPT)
131 static char* Log_formatTraceEntry(traceEntry* cur_entry);
132 static void Log_output(enum LOG_LEVELS log_level, const char *msg);
133 static void Log_posttrace(enum LOG_LEVELS log_level, traceEntry* cur_entry);
134 #endif
135 static void Log_trace(enum LOG_LEVELS log_level, const char *buf);
136 #if 0
137 static FILE* Log_destToFile(const char *dest);
138 static int Log_compareEntries(const char *entry1, const char *entry2);
139 #endif
140
141 static int sametime_count = 0;
142 #if defined(GETTIMEOFDAY)
143 struct timeval now_ts, last_ts;
144 #else
145 struct timeb now_ts, last_ts;
146 #endif
147 #if defined (IOT_CONNECT) || defined(IOT_LITEOS_ADAPT)
148 static char msg_buf[100];
149 #else
150 static char msg_buf[512];
151 #endif
152
153 #if defined(_WIN32) || defined(_WIN64) || defined(COMPAT_CMSIS)
154 mutex_type log_mutex;
155 #else
156 static pthread_mutex_t log_mutex_store = PTHREAD_MUTEX_INITIALIZER;
157 static mutex_type log_mutex = &log_mutex_store;
158 #endif
159
160
Log_initialize(Log_nameValue * info)161 int Log_initialize(Log_nameValue* info)
162 {
163 #if defined (IOT_CONNECT) || defined(IOT_LITEOS_ADAPT)
164 (void)info;
165 return -1;
166 #else
167 int rc = SOCKET_ERROR;
168 char* envval = NULL;
169 #if !defined(_WIN32) && !defined(_WIN64)
170 struct stat buf;
171 #endif
172
173 if ((trace_queue = malloc(sizeof(traceEntry) * trace_settings.max_trace_entries)) == NULL)
174 goto exit;
175 trace_queue_size = trace_settings.max_trace_entries;
176
177 if ((envval = getenv("MQTT_C_CLIENT_TRACE")) != NULL && strlen(envval) > 0)
178 {
179 if (strcmp(envval, "ON") == 0 || (trace_destination = fopen(envval, "w")) == NULL)
180 trace_destination = stdout;
181 else
182 {
183 size_t namelen = 0;
184
185 if ((trace_destination_name = malloc(strlen(envval) + 1)) == NULL)
186 {
187 free(trace_queue);
188 goto exit;
189 }
190 strcpy(trace_destination_name, envval);
191 namelen = strlen(envval) + 3;
192 if ((trace_destination_backup_name = malloc(namelen)) == NULL)
193 {
194 free(trace_queue);
195 free(trace_destination_name);
196 goto exit;
197 }
198 if (snprintf(trace_destination_backup_name, namelen, "%s.0", trace_destination_name) >= namelen)
199 trace_destination_backup_name[namelen-1] = '\0';
200 }
201 }
202 if ((envval = getenv("MQTT_C_CLIENT_TRACE_MAX_LINES")) != NULL && strlen(envval) > 0)
203 {
204 max_lines_per_file = atoi(envval);
205 if (max_lines_per_file <= 0)
206 max_lines_per_file = 1000;
207 }
208 if ((envval = getenv("MQTT_C_CLIENT_TRACE_LEVEL")) != NULL && strlen(envval) > 0)
209 {
210 if (strcmp(envval, "MAXIMUM") == 0 || strcmp(envval, "TRACE_MAXIMUM") == 0)
211 trace_settings.trace_level = TRACE_MAXIMUM;
212 else if (strcmp(envval, "MEDIUM") == 0 || strcmp(envval, "TRACE_MEDIUM") == 0)
213 trace_settings.trace_level = TRACE_MEDIUM;
214 else if (strcmp(envval, "MINIMUM") == 0 || strcmp(envval, "TRACE_MINIMUM") == 0)
215 trace_settings.trace_level = TRACE_MINIMUM;
216 else if (strcmp(envval, "PROTOCOL") == 0 || strcmp(envval, "TRACE_PROTOCOL") == 0)
217 trace_output_level = TRACE_PROTOCOL;
218 else if (strcmp(envval, "ERROR") == 0 || strcmp(envval, "TRACE_ERROR") == 0)
219 trace_output_level = LOG_ERROR;
220 }
221 Log_output(TRACE_MINIMUM, "=========================================================");
222 Log_output(TRACE_MINIMUM, " Trace Output");
223 if (info)
224 {
225 while (info->name)
226 {
227 snprintf(msg_buf, sizeof(msg_buf), "%s: %s", info->name, info->value);
228 Log_output(TRACE_MINIMUM, msg_buf);
229 info++;
230 }
231 }
232 #if !defined(_WIN32) && !defined(_WIN64)
233 if (stat("/proc/version", &buf) != -1)
234 {
235 FILE* vfile;
236
237 if ((vfile = fopen("/proc/version", "r")) != NULL)
238 {
239 int len;
240
241 strcpy(msg_buf, "/proc/version: ");
242 len = strlen(msg_buf);
243 if (fgets(&msg_buf[len], sizeof(msg_buf) - len, vfile))
244 Log_output(TRACE_MINIMUM, msg_buf);
245 fclose(vfile);
246 }
247 }
248 #endif
249 Log_output(TRACE_MINIMUM, "=========================================================");
250 exit:
251 return rc;
252 #endif
253 }
254
255
Log_setTraceCallback(Log_traceCallback * callback)256 void Log_setTraceCallback(Log_traceCallback* callback)
257 {
258 trace_callback = callback;
259 }
260
261
Log_setTraceLevel(enum LOG_LEVELS level)262 void Log_setTraceLevel(enum LOG_LEVELS level)
263 {
264 if (level <= LOG_ERROR) /* the lowest we can go is LOG_ERROR */
265 trace_settings.trace_level = level;
266 trace_output_level = level;
267 }
268
269
Log_terminate(void)270 void Log_terminate(void)
271 {
272 #if defined (IOT_CONNECT) || defined(IOT_LITEOS_ADAPT)
273 return;
274 #else
275 free(trace_queue);
276 trace_queue = NULL;
277 trace_queue_size = 0;
278 if (trace_destination)
279 {
280 if (trace_destination != stdout)
281 fclose(trace_destination);
282 trace_destination = NULL;
283 }
284 if (trace_destination_name) {
285 free(trace_destination_name);
286 trace_destination_name = NULL;
287 }
288 if (trace_destination_backup_name) {
289 free(trace_destination_backup_name);
290 trace_destination_backup_name = NULL;
291 }
292 start_index = -1;
293 next_index = 0;
294 trace_output_level = INVALID_LEVEL;
295 sametime_count = 0;
296 #endif
297 }
298
299
Log_pretrace(void)300 static traceEntry* Log_pretrace(void)
301 {
302 traceEntry *cur_entry = NULL;
303
304 /* calling ftime/gettimeofday seems to be comparatively expensive, so we need to limit its use */
305 if (++sametime_count % 20 == 0)
306 {
307 #if defined(GETTIMEOFDAY)
308 gettimeofday(&now_ts, NULL);
309 if (now_ts.tv_sec != last_ts.tv_sec || now_ts.tv_usec != last_ts.tv_usec)
310 #else
311 ftime(&now_ts);
312 if (now_ts.time != last_ts.time || now_ts.millitm != last_ts.millitm)
313 #endif
314 {
315 sametime_count = 0;
316 last_ts = now_ts;
317 }
318 }
319
320 if (trace_queue_size != trace_settings.max_trace_entries)
321 {
322 traceEntry* new_trace_queue = malloc(sizeof(traceEntry) * trace_settings.max_trace_entries);
323
324 if (new_trace_queue == NULL)
325 goto exit;
326 memcpy(new_trace_queue, trace_queue, min(trace_queue_size, trace_settings.max_trace_entries) * sizeof(traceEntry));
327 free(trace_queue);
328 trace_queue = new_trace_queue;
329 trace_queue_size = trace_settings.max_trace_entries;
330
331 if (start_index > trace_settings.max_trace_entries + 1 ||
332 next_index > trace_settings.max_trace_entries + 1)
333 {
334 start_index = -1;
335 next_index = 0;
336 }
337 }
338
339 /* add to trace buffer */
340 cur_entry = &trace_queue[next_index];
341 if (next_index == start_index) /* means the buffer is full */
342 {
343 if (++start_index == trace_settings.max_trace_entries)
344 start_index = 0;
345 } else if (start_index == -1)
346 start_index = 0;
347 if (++next_index == trace_settings.max_trace_entries)
348 next_index = 0;
349 exit:
350 return cur_entry;
351 }
352
353 #if !defined (IOT_CONNECT) && !defined (IOT_LITEOS_ADAPT)
Log_formatTraceEntry(traceEntry * cur_entry)354 static char* Log_formatTraceEntry(traceEntry* cur_entry)
355 {
356 struct tm *timeinfo;
357 int buf_pos = 31;
358
359 #if defined(GETTIMEOFDAY)
360 timeinfo = localtime((time_t *)&cur_entry->ts.tv_sec);
361 #else
362 timeinfo = localtime(&cur_entry->ts.time);
363 #endif
364 strftime(&msg_buf[7], 80, "%Y%m%d %H%M%S ", timeinfo);
365 #if defined(GETTIMEOFDAY)
366 snprintf(&msg_buf[22], sizeof(msg_buf)-22, ".%.3lu ", cur_entry->ts.tv_usec / 1000L);
367 #else
368 snprintf(&msg_buf[22], sizeof(msg_buf)-22, ".%.3hu ", cur_entry->ts.millitm);
369 #endif
370 buf_pos = 27;
371
372 snprintf(msg_buf, sizeof(msg_buf), "(%.4d)", cur_entry->sametime_count);
373 msg_buf[6] = ' ';
374
375 if (cur_entry->has_rc == 2)
376 strncpy(&msg_buf[buf_pos], cur_entry->name, sizeof(msg_buf)-buf_pos);
377 else
378 {
379 const char *format = Messages_get(cur_entry->number, cur_entry->level);
380 if (cur_entry->has_rc == 1)
381 snprintf(&msg_buf[buf_pos], sizeof(msg_buf)-buf_pos, format, cur_entry->thread_id,
382 cur_entry->depth, "", cur_entry->depth, cur_entry->name, cur_entry->line, cur_entry->rc);
383 else
384 snprintf(&msg_buf[buf_pos], sizeof(msg_buf)-buf_pos, format, cur_entry->thread_id,
385 cur_entry->depth, "", cur_entry->depth, cur_entry->name, cur_entry->line);
386 }
387 return msg_buf;
388 }
389
390
Log_output(enum LOG_LEVELS log_level,const char * msg)391 static void Log_output(enum LOG_LEVELS log_level, const char *msg)
392 {
393 if (trace_destination)
394 {
395 fprintf(trace_destination, "%s\n", msg);
396
397 if (trace_destination != stdout && ++lines_written >= max_lines_per_file)
398 {
399
400 fclose(trace_destination);
401 _unlink(trace_destination_backup_name); /* remove any old backup trace file */
402 rename(trace_destination_name, trace_destination_backup_name); /* rename recently closed to backup */
403 trace_destination = fopen(trace_destination_name, "w"); /* open new trace file */
404 if (trace_destination == NULL)
405 trace_destination = stdout;
406 lines_written = 0;
407 }
408 else
409 fflush(trace_destination);
410 }
411
412 if (trace_callback)
413 (*trace_callback)(log_level, msg);
414 }
415 #endif
416
417
Log_posttrace(enum LOG_LEVELS log_level,traceEntry * cur_entry)418 static void Log_posttrace(enum LOG_LEVELS log_level, traceEntry* cur_entry)
419 {
420 #if defined (IOT_CONNECT) || defined(IOT_LITEOS_ADAPT)
421 (void)log_level;
422 (void)cur_entry;
423 #else
424 if (((trace_output_level == -1) ? log_level >= trace_settings.trace_level : log_level >= trace_output_level))
425 {
426 char* msg = NULL;
427
428 if (trace_destination || trace_callback)
429 msg = &Log_formatTraceEntry(cur_entry)[7];
430
431 Log_output(log_level, msg);
432 }
433 #endif
434 }
435
436
Log_trace(enum LOG_LEVELS log_level,const char * buf)437 static void Log_trace(enum LOG_LEVELS log_level, const char *buf)
438 {
439 traceEntry *cur_entry = NULL;
440
441 if (trace_queue == NULL)
442 return;
443
444 cur_entry = Log_pretrace();
445
446 memcpy(&(cur_entry->ts), &now_ts, sizeof(now_ts));
447 cur_entry->sametime_count = sametime_count;
448
449 cur_entry->has_rc = 2;
450 strncpy(cur_entry->name, buf, sizeof(cur_entry->name));
451 cur_entry->name[MAX_FUNCTION_NAME_LENGTH] = '\0';
452
453 Log_posttrace(log_level, cur_entry);
454 }
455
456
457 /**
458 * Log a message. If possible, all messages should be indexed by message number, and
459 * the use of the format string should be minimized or negated altogether. If format is
460 * provided, the message number is only used as a message label.
461 * @param log_level the log level of the message
462 * @param msgno the id of the message to use if the format string is NULL
463 * @param aFormat the printf format string to be used if the message id does not exist
464 * @param ... the printf inserts
465 */
Log(enum LOG_LEVELS log_level,int msgno,const char * format,...)466 void Log(enum LOG_LEVELS log_level, int msgno, const char *format, ...)
467 {
468 if (log_level >= trace_settings.trace_level)
469 {
470 const char *temp = NULL;
471 va_list args;
472
473 /* we're using a static character buffer, so we need to make sure only one thread uses it at a time */
474 Thread_lock_mutex(log_mutex);
475 if (format == NULL && (temp = Messages_get(msgno, log_level)) != NULL)
476 format = temp;
477
478 va_start(args, format);
479 vsnprintf(msg_buf, sizeof(msg_buf), format, args);
480
481 #if defined(IOT_CONNECT)
482 atiny_printf("%s\n", msg_buf);
483 #elif defined(IOT_LITEOS_ADAPT)
484 osal_printk("%s\n", msg_buf);
485 #else
486 Log_trace(log_level, msg_buf);
487 #endif
488 va_end(args);
489 Thread_unlock_mutex(log_mutex);
490 }
491 }
492
493
494 /**
495 * The reason for this function is to make trace logging as fast as possible so that the
496 * function exit/entry history can be captured by default without unduly impacting
497 * performance. Therefore it must do as little as possible.
498 * @param log_level the log level of the message
499 * @param msgno the id of the message to use if the format string is NULL
500 * @param aFormat the printf format string to be used if the message id does not exist
501 * @param ... the printf inserts
502 */
Log_stackTrace(enum LOG_LEVELS log_level,int msgno,thread_id_type thread_id,int current_depth,const char * name,int line,int * rc)503 void Log_stackTrace(enum LOG_LEVELS log_level, int msgno, thread_id_type thread_id, int current_depth, const char* name, int line, int* rc)
504 {
505 traceEntry *cur_entry = NULL;
506
507 if (trace_queue == NULL)
508 return;
509
510 if (log_level < trace_settings.trace_level)
511 return;
512
513 Thread_lock_mutex(log_mutex);
514 cur_entry = Log_pretrace();
515
516 memcpy(&(cur_entry->ts), &now_ts, sizeof(now_ts));
517 cur_entry->sametime_count = sametime_count;
518 cur_entry->number = msgno;
519 cur_entry->thread_id = thread_id;
520 cur_entry->depth = current_depth;
521 strcpy(cur_entry->name, name);
522 cur_entry->level = log_level;
523 cur_entry->line = line;
524 if (rc == NULL)
525 cur_entry->has_rc = 0;
526 else
527 {
528 cur_entry->has_rc = 1;
529 cur_entry->rc = *rc;
530 }
531
532 Log_posttrace(log_level, cur_entry);
533 Thread_unlock_mutex(log_mutex);
534 }
535
536
537 #if 0
538 static FILE* Log_destToFile(const char *dest)
539 {
540 FILE* file = NULL;
541
542 if (strcmp(dest, "stdout") == 0)
543 file = stdout;
544 else if (strcmp(dest, "stderr") == 0)
545 file = stderr;
546 else
547 {
548 if (strstr(dest, "FFDC"))
549 file = fopen(dest, "ab");
550 else
551 file = fopen(dest, "wb");
552 }
553 return file;
554 }
555
556
557 static int Log_compareEntries(const char *entry1, const char *entry2)
558 {
559 int comp = strncmp(&entry1[7], &entry2[7], 19);
560
561 /* if timestamps are equal, use the sequence numbers */
562 if (comp == 0)
563 comp = strncmp(&entry1[1], &entry2[1], 4);
564
565 return comp;
566 }
567
568
569 /**
570 * Write the contents of the stored trace to a stream
571 * @param dest string which contains a file name or the special strings stdout or stderr
572 */
573 int Log_dumpTrace(char* dest)
574 {
575 FILE* file = NULL;
576 ListElement* cur_trace_entry = NULL;
577 const int msgstart = 7;
578 int rc = -1;
579 int trace_queue_index = 0;
580
581 if ((file = Log_destToFile(dest)) == NULL)
582 {
583 Log(LOG_ERROR, 9, NULL, "trace", dest, "trace entries");
584 goto exit;
585 }
586
587 fprintf(file, "=========== Start of trace dump ==========\n");
588 /* Interleave the log and trace entries together appropriately */
589 ListNextElement(trace_buffer, &cur_trace_entry);
590 trace_queue_index = start_index;
591 if (trace_queue_index == -1)
592 trace_queue_index = next_index;
593 else
594 {
595 Log_formatTraceEntry(&trace_queue[trace_queue_index++]);
596 if (trace_queue_index == trace_settings.max_trace_entries)
597 trace_queue_index = 0;
598 }
599 while (cur_trace_entry || trace_queue_index != next_index)
600 {
601 if (cur_trace_entry && trace_queue_index != -1)
602 { /* compare these timestamps */
603 if (Log_compareEntries((char*)cur_trace_entry->content, msg_buf) > 0)
604 cur_trace_entry = NULL;
605 }
606
607 if (cur_trace_entry)
608 {
609 fprintf(file, "%s\n", &((char*)(cur_trace_entry->content))[msgstart]);
610 ListNextElement(trace_buffer, &cur_trace_entry);
611 }
612 else
613 {
614 fprintf(file, "%s\n", &msg_buf[7]);
615 if (trace_queue_index != next_index)
616 {
617 Log_formatTraceEntry(&trace_queue[trace_queue_index++]);
618 if (trace_queue_index == trace_settings.max_trace_entries)
619 trace_queue_index = 0;
620 }
621 }
622 }
623 fprintf(file, "========== End of trace dump ==========\n\n");
624 if (file != stdout && file != stderr && file != NULL)
625 fclose(file);
626 rc = 0;
627 exit:
628 return rc;
629 }
630 #endif
631
632
633