[PATCH v3 23/23] doc: Update logging documentation

[Sean Anderson]

On 10/27/20 5:00 PM, Heinrich Schuchardt wrote:
> On 17.10.20 20:07, Sean Anderson wrote:
>> This updates logging documentation with some examples of the new commands
>> added in the previous commits. It also removes some items from the to-do
>> list which have been implemented.
>>
>> Signed-off-by: Sean Anderson <seanga2 at gmail.com>
>> Reviewed-by: Simon Glass <sjg at chromium.org>
>> ---
>>
>> Changes in v3:
>> - Fix heading level of Filters section
>> - Remove a few more already-implemented features from the TODO list
>>
>> Changes in v2:
>> - Add a few informational commands
>> - Clarify wording of filter documentation
>> - Include enum definitions instead of re-documenting them
>> - Reorganize log documentation; related sections should now be more proximate
>>
>>  doc/develop/logging.rst | 242 +++++++++++++++++++---------------------
>>  1 file changed, 115 insertions(+), 127 deletions(-)
>>
>> diff --git a/doc/develop/logging.rst b/doc/develop/logging.rst
>> index 6a22062073..2b87bc2b4f 100644
>> --- a/doc/develop/logging.rst
>> +++ b/doc/develop/logging.rst
>> @@ -21,23 +21,13 @@ is visible from the basic console output.
>>  U-Boot's logging feature aims to satisfy this goal for both users and
>>  developers.
>>
>> -
>>  Logging levels
>>  --------------
>>
>> -There are a number logging levels available, in increasing order of verbosity:
>> -
>> -* LOGL_EMERG - Printed before U-Boot halts
>> -* LOGL_ALERT - Indicates action must be taken immediate or U-Boot will crash
>> -* LOGL_CRIT - Indicates a critical error that will cause boot failure
>> -* LOGL_ERR - Indicates an error that may cause boot failure
>> -* LOGL_WARNING - Warning about an unexpected condition
>> -* LOGL_NOTE - Important information about progress
>> -* LOGL_INFO - Information about normal boot progress
>> -* LOGL_DEBUG - Debug information (useful for debugging a driver or subsystem)
>> -* LOGL_DEBUG_CONTENT - Debug message showing full message content
>> -* LOGL_DEBUG_IO - Debug message showing hardware I/O access
>> +There are a number logging levels available.
>>
>> +.. kernel-doc:: include/log.h
>> +   :identifiers: log_level_t
>>
>>  Logging category
>>  ----------------
>> @@ -46,16 +36,8 @@ Logging can come from a wide variety of places within U-Boot. Each log message
>>  has a category which is intended to allow messages to be filtered according to
>>  their source.
>>
>> -The following main categories are defined:
>> -
>> -* LOGC_NONE - Unknown category (e.g. a debug() statement)
>> -* UCLASS\_... - Related to a particular uclass (e.g. UCLASS_USB)
>> -* LOGC_ARCH - Related to architecture-specific code
>> -* LOGC_BOARD - Related to board-specific code
>> -* LOGC_CORE - Related to core driver-model support
>> -* LOGC_DT - Related to device tree control
>> -* LOGC_EFI - Related to EFI implementation
>> -
>> +.. kernel-doc:: include/log.h
>> +   :identifiers: log_category_t
>>
>>  Enabling logging
>>  ----------------
>> @@ -72,7 +54,6 @@ If CONFIG_LOG is not set, then no logging will be available.
>>  The above have SPL and TPL versions also, e.g. CONFIG_SPL_LOG_MAX_LEVEL and
>>  CONFIG_TPL_LOG_MAX_LEVEL.
>>
>> -
>>  Temporary logging within a single file
>>  --------------------------------------
>>
>> @@ -86,46 +67,8 @@ to enable building in of all logging statements in a single file. Put it at
>>  the top of the file, before any #includes.
>>
>>  To actually get U-Boot to output this you need to also set the default logging
>> -level - e.g. set CONFIG_LOG_DEFAULT_LEVEL to 7 (LOGL_DEBUG) or more. Otherwise
>> -debug output is suppressed and will not be generated.
>> -
>> -
>> -Convenience functions
>> ----------------------
>> -
>> -A number of convenience functions are available to shorten the code needed
>> -for logging:
>> -
>> -* log_err(_fmt...)
>> -* log_warning(_fmt...)
>> -* log_notice(_fmt...)
>> -* log_info(_fmt...)
>> -* log_debug(_fmt...)
>> -* log_content(_fmt...)
>> -* log_io(_fmt...)
>> -
>> -With these the log level is implicit in the name. The category is set by
>> -LOG_CATEGORY, which you can only define once per file, above all #includes, e.g.
>> -
>> -.. code-block:: c
>> -
>> -	#define LOG_CATEGORY LOGC_ALLOC
>> -
>> -Remember that all uclasses IDs are log categories too.
>> -
>> -
>> -Log command
>> ------------
>> -
>> -The 'log' command provides access to several features:
>> -
>> -* level - access the default log level
>> -* format - access the console log format
>> -* rec - output a log record
>> -* test - run tests
>> -
>> -Type 'help log' for details.
>> -
>> +level - e.g. set CONFIG_LOG_DEFAULT_LEVEL to 7 (:c:type:`LOGL_DEBUG`) or more.
>> +Otherwise debug output is suppressed and will not be generated.
>>
>>  Using DEBUG
>>  -----------
>> @@ -142,51 +85,6 @@ at the top of a file, then it takes precedence. This means that debug()
>>  statements will result in output to the console and this output will not be
>>  logged.
>>
>> -
>> -Logging destinations
>> ---------------------
>> -
>> -If logging information goes nowhere then it serves no purpose. U-Boot provides
>> -several possible determinations for logging information, all of which can be
>> -enabled or disabled independently:
>> -
>> -* console - goes to stdout
>> -* syslog - broadcast RFC 3164 messages to syslog servers on UDP port 514
>> -
>> -The syslog driver sends the value of environmental variable 'log_hostname' as
>> -HOSTNAME if available.
>> -
>> -
>> -Log format
>> -----------
>> -
>> -You can control the log format using the 'log format' command. The basic
>> -format is::
>> -
>> -   LEVEL.category,file.c:123-func() message
>> -
>> -In the above, file.c:123 is the filename where the log record was generated and
>> -func() is the function name. By default ('log format default') only the
>> -function name and message are displayed on the console. You can control which
>> -fields are present, but not the field order.
>> -
>> -
>> -Filters
>> --------
>> -
>> -Filters are attached to log drivers to control what those drivers emit. Only
>> -records that pass through the filter make it to the driver.
>> -
>> -Filters can be based on several criteria:
>> -
>> -* maximum log level
>> -* in a set of categories
>> -* in a set of files
>> -
>> -If no filters are attached to a driver then a default filter is used, which
>> -limits output to records with a level less than CONFIG_MAX_LOG_LEVEL.
>> -
>> -
>>  Logging statements
>>  ------------------
>>
>> @@ -210,6 +108,112 @@ can be used whenever your function returns an error value:
>>  This will write a log record when an error code is detected (a value < 0). This
>>  can make it easier to trace errors that are generated deep in the call stack.
>>
>> +Convenience functions
>> +~~~~~~~~~~~~~~~~~~~~~
>> +
>> +A number of convenience functions are available to shorten the code needed
>> +for logging:
>> +
>> +* log_err(_fmt...)
>> +* log_warning(_fmt...)
>> +* log_notice(_fmt...)
>> +* log_info(_fmt...)
>> +* log_debug(_fmt...)
>> +* log_content(_fmt...)
>> +* log_io(_fmt...)
>> +
>> +With these the log level is implicit in the name. The category is set by
>> +LOG_CATEGORY, which you can only define once per file, above all #includes, e.g.
>> +
>> +.. code-block:: c
>> +
>> +	#define LOG_CATEGORY LOGC_ALLOC
>> +
>> +Remember that all uclasses IDs are log categories too.
>> +
>> +Logging destinations
>> +--------------------
>> +
>> +If logging information goes nowhere then it serves no purpose. U-Boot provides
>> +several possible determinations for logging information, all of which can be
>> +enabled or disabled independently:
>> +
>> +* console - goes to stdout
>> +* syslog - broadcast RFC 3164 messages to syslog servers on UDP port 514
>> +
>> +The syslog driver sends the value of environmental variable 'log_hostname' as
>> +HOSTNAME if available.
>> +
>> +Filters
>> +-------
>> +
>> +Filters are attached to log drivers to control what those drivers emit. FIlters
>> +can either allow or deny a log message when they match it. Only records which
>> +are allowed by a filter make it to the driver.
>> +
>> +Filters can be based on several criteria:
>> +
>> +* minimum or maximum log level
>> +* in a set of categories
>> +* in a set of files
>> +
>> +If no filters are attached to a driver then a default filter is used, which
>> +limits output to records with a level less than CONFIG_MAX_LOG_LEVEL.
>> +
>> +Log command
>> +-----------
>> +
>> +The 'log' command provides access to several features:
>> +
>> +* level - get/set the log level
>> +* categories - list log categories
> 
> How does the user get the sorted list of all level texts?

run `log level` without arguments. I suppose the description should be
expanded...

> 
>> +* drivers - list log drivers
>> +* filter-list - list filters
>> +* filter-add - add a new filter
>> +* filter-remove - remove filters
>> +* format - access the console log format
>> +* rec - output a log record
>> +
>> +Type 'help log' for details.
>> +
>> +Log format
>> +~~~~~~~~~~
>> +
>> +You can control the log format using the 'log format' command. The basic
>> +format is::
>> +
>> +   LEVEL.category,file.c:123-func() message
>> +
>> +In the above, file.c:123 is the filename where the log record was generated and
>> +func() is the function name. By default ('log format default') only the message
>> +is displayed on the console. You can control which fields are present, but not
>> +the field order.
>> +
>> +Adding Filters
>> +~~~~~~~~~~~~~~
>> +
>> +To add new filters at runtime, use the 'log filter-add' command. For example, to
>> +suppress messages from the SPI subsystem, run::
>> +
>> +    log filter-add -D -c spi
>> +
>> +You will also need to add another filter to allow other messages (because the
>> +default filter no longer applies)::
>> +
>> +    log filter-add -A -l debug
> 
> Are level numbers also accepted?

Yes.

> 
> How do you add a file filter?

-f file1.c,file2.c

> I would prefer a table with all parameters used for filtering with an
> explanation, e.g.
> 
> -A - allow filter
> -D - deny filter
> -c <category> - category to which the filter applies
> -l <level> - for deny filter deny all messages with a level less or
> equal <level>, for allow filter allow all messages with a level greater
> or equal <level>
> ...
> 
> Put the examples under the table of parameters.

As discussed before, I am worried that any such table will drift away
from the help text. For an example of this in action, see [1]. I would
much rather provide a few examples, and the direct users to the help
text.

[1] https://patchwork.ozlabs.org/project/uboot/patch/20201026154024.117057-1-tyhicks@linux.microsoft.com/

> 
> Best regards
> 
> Heinrich
> 
>> +
>> +To view active filters, use the 'log filter-list' command. Some example output
>> +is::
>> +
>> +    => log filter-list
>> +    num policy level           categories files
>> +      0   deny <=IO                   spi
> 
> An extra space after '<=' would make the output line more readable.

Ok.

> 
> Best regards
> 
> Heinrich
> 
>> +      1  allow <=DEBUG
>> +
>> +Note that filters are processed in-order from top to bottom, not in the order of
>> +their filter number. Filters are added to the top of the list if they deny when
>> +they match, and to the bottom if they allow when they match. For more
>> +information, consult the usage of the 'log' command, by running 'help log'.
>>
>>  Code size
>>  ---------
>> @@ -226,12 +230,11 @@ The last option turns every debug() statement into a logging call, which
>>  bloats the code hugely. The advantage is that it is then possible to enable
>>  all logging within U-Boot.
>>
>> -
>>  To Do
>>  -----
>>
>>  There are lots of useful additions that could be made. None of the below is
>> -implemented! If you do one, please add a test in test/py/tests/test_log.py
>> +implemented! If you do one, please add a test in test/log/log_test.c
>>
>>  Convenience functions to support setting the category:
>>
>> @@ -253,25 +256,15 @@ Convert error() statements in the code to log() statements
>>
>>  Figure out what to do with BUG(), BUG_ON() and warn_non_spl()
>>
>> -Figure out what to do with assert()
>> -
>>  Add a way to browse log records
>>
>>  Add a way to record log records for browsing using an external tool
>>
>> -Add commands to add and remove filters
>> -
>>  Add commands to add and remove log devices
>>
>>  Allow sharing of printf format strings in log records to reduce storage size
>>  for large numbers of log records
>>
>> -Add a command-line option to sandbox to set the default logging level
>> -
>> -Convert core driver model code to use logging
>> -
>> -Convert uclasses to use logging with the correct category
>> -
>>  Consider making log() calls emit an automatic newline, perhaps with a logn()
>>  function to avoid that
>>
>> @@ -282,12 +275,7 @@ number dropped due to them being generated before the log system was ready.
>>
>>  Add a printf() format string pragma so that log statements are checked properly
>>
>> -Enhance the log console driver to show level / category / file / line
>> -information
>> -
>> -Add a command to add new log records and delete existing records.
>> -
>> -Provide additional log() functions - e.g. logc() to specify the category
>> +Add a command to delete existing log records.
>>
>>  Logging API
>>  -----------
>>
>