docs/development/serial_printf_debugging.md

   1 # Serial printf style debugging
   2
   3 ## Overview
   4
   5 INAV offers a function to use serial `printf` style debugging.
   6
   7 This provides a simple and intuitive debugging facility. This facility is only available after the serial sub-system has been initialised, which should be adequate for all but the most hard-core debugging requirements.
   8
   9 In order to use this feature, the source file must include `common/log.h`.
  10
  11 ## CLI settings
  12
  13 It is necessary to set a serial port for serial logging using the function mask `FUNCTION_LOG`, 32768. For convenience this may be shared with MSP (mask 1), but no other function.
  14 For example, on a VCP port.
  15
  16 ```
  17 serial 20 32769 115200 115200 0 115200
  18 ```
  19
  20 If the port is shared, it will be reused with extant baud rate settings; if the port is not shared it is opened at 921600 baud.
  21
  22 There are two run time settings that control the verbosity, the most verbose settings being:
  23
  24 ```
  25 log_level = DEBUG
  26 Allowed values: ERROR, WARNING, INFO, VERBOSE, DEBUG
  27
  28 log_topics = 0
  29 Allowed range: 0 - 4294967295
  30
  31 ```
  32
  33 The use of level and topics is described in the following sections.
  34
  35 ## LOG LEVELS
  36
  37 Log levels are defined in `src/main/common/log.h`, at the time of writing these include (in ascending order):
  38
  39 * LOG_LEVEL_ERROR
  40 * LOG_LEVEL_WARNING
  41 * LOG_LEVEL_INFO
  42 * LOG_LEVEL_VERBOSE
  43 * LOG_LEVEL_DEBUG
  44
  45 These are used at both compile time and run time.
  46
  47 At compile time, a maximum level may be defined. As of INAV 2.3, for F3 targets the maximum level is ERROR, for F4/F7 the maximum level is DEBUG.
  48
  49 At run time, the level defines the level that will be displayed, so for a F4 or F7 target that has compile time suport for all log levels, if the CLI sets
  50 ```
  51 log_level = INFO
  52 ```
  53 then only `ERROR`, `WARNING` and `INFO` levels will be output.
  54
  55 ## Log Topic
  56
  57 Log topics are defined in `src/main/common/log.h`, at the time of writing:
  58
  59 * LOG_TOPIC_SYSTEM
  60 * LOG_TOPIC_GYRO
  61 * LOG_TOPIC_BARO
  62 * LOG_TOPIC_PITOT
  63 * LOG_TOPIC_PWM
  64 * LOG_TOPIC_TIMER
  65 * LOG_TOPIC_IMU
  66 * LOG_TOPIC_TEMPERATURE
  67 * LOG_TOPIC_POS_ESTIMATOR
  68 * LOG_TOPIC_VTX
  69 * LOG_TOPIC_OSD
  70
  71 Topics are stored as masks (SYSTEM=1 ... OSD=1024) and may be used to unconditionally display log messages.
  72
  73 If the CLI `log_topics` is non-zero, then all topics matching the mask will be displayed regardless of `log_level`. Setting `log_topics` to 4294967295 (all bits set) will display all log messages regardless of run time level (but still constrained by compile time settings), so F3 will still only display ERROR level messages.
  74
  75 ## Code usage
  76
  77 A set of macros `LOG_ERROR()` (log error) through `LOG_DEBUG()` (log debug) may be used, subject to compile time log level constraints. These provide `printf` style logging for a given topic.
  78
  79 Note that the `topic` is specified without the `LOG_TOPIC_` prefix:
  80
  81 ```
  82 //  LOG_DEBUG(topic, fmt, ...)
  83 LOG_DEBUG(SYSTEM, "This is %s topic debug message, value %d", "system", 42);
  84 ```
  85
  86 It is also possible to dump a hex representation of arbitrary  data, using functions named variously `LOG_BUFFER_` (`ERROR`) and `LOG_BUF_` (anything else, alas) e.g.:
  87
  88 ```
  89 // LOG_BUFFER_ERROR(topic, buf, size)
  90 // LOG_BUF_DEBUG(topic, buf, size)
  91
  92 struct {...} tstruct;
  93 ...
  94 LOG_BUF_DEBUG(TEMPERATURE, &tstruct, sizeof(tstruct));
  95 ```
  96
  97 ## Output Support
  98
  99 Log messages are transmitted through the `FUNCTION_LOG` serial port as MSP messages (`MSP_DEBUGMSG`). It is possible to use any serial terminal to display these messages, however it is advisable to use an application that understands `MSP_DEBUGMSG` in order to maintain readability (in a raw serial terminal the MSP message envelope may result in the display of strange characters). `MSP_DEBUGMSG` aware applications include:
 100
 101 * [dbg-tool](https://codeberg.org/stronnag/dbg-tool)
 102 * [INAV Configurator](https://github.com/iNavFlight/inav-configurator)
 103 * [mwp](https://github.com/stronnag/mwptools)
 104
 105 In addtion:
 106
 107 * [msp-tool](https://github.com/fiam/msp-tool) is obsolete and has limited OS support.
 108
 109 For example, with the final lines of `src/main/fc/fc_init.c` set to:
 110
 111 ```
 112  LOG_ERROR(SYSTEM, "Init is complete");
 113  systemState |= SYSTEM_STATE_READY;
 114 ```
 115
 116 and the following CLI settings:
 117
 118 ```
 119 serial 20 32769 115200 115200 0 115200
 120 set log_level = DEBUG
 121 set log_topics = 4294967295
 122 ```
 123
 124 The output will be formatted as follows:
 125
 126 ```
 127 # dbg-tool
 128 [dbg-tool] 12:46:49.909079 DBG: [     3.967] Init is complete
 129
 130 # mwp (stderr log file)
 131 2020-02-02T19:09:02+0000 DEBUG:[     3.968] Init is complete
 132
 133 # msp-tool
 134 [DEBUG] [     3.967] Init is complete
 135 ```
 136
 137 For the Configurator, debug messages are shown in the developer console log.
 138
 139 Note: The numeric value in square brackets is the FC uptime in seconds.