Page History

Debug Output (SYSLOG) Issues

Lately, I have starting thinking a little more about the SYSLOG functions in general (as well as all of those debug macros). I think I am coming to the conclusion that there needs to be some things done.

...

Here are some of the issues of the current implementation that bother me:

Use of File Descriptors

In the default case, the debug output goes out on file descriptor 1, stdout. But if you think about that, it is a little crazy.

...

If you are redirecting stdout to a file, for example, then the debug information could go into your file, corrupting the output that you wanted. As another perverse example, try enabling network debug output using a Telnet session. That is an interesting exercise for anyone who like to see infinite loops: Telnet I/O generates debug output, the debug output goes to the Telnet network connection, which generates more network debug output, and on and one.

Interrupt Handlers

Output from interrupt handlers, of course, cannot use the console device at all. File descriptor I/O is not permitted from interrupt handlers. Attempts to do "normal" SYSLOG output from interrupt handlers will just result in the output going to the bit bucket.

Low-Level Serial Driver

The usual workaround to get debug output from interrupt handlers is to use the low-level serial I/O from interrupt handlers. But there are issues with this as well:

...

• The low level serial output also interacts the serial driver itself making other use of the console impossible. Even, in some cases on some platforms, locking up the serial driver.

Interrupt Buffer

Another way to handle interrupt level output is supported. This is the only other option available if a Serial Console is not being used. This second option is enabled with CONFIG_SYSLOG_INTBUFFER.

In this case, syslog output generated from interrupt level logic will simply be buffered in memory. Then, later, when the next non-interrupt level syslog output is generated, the buffer interrupt level output will performed. This works because it essentially defers the syslog output generated from interrupt handlers until the next opportunity to perform normal output.

Asynchronous Output

Another syslog related issue is the asynchronous behavior with debug output from interrupt handlers. The normal debug output goes to the serial driver and is buffered for sending there. The size of the serial RX buffer is configurable. At any given point in time, the current output is behind realtme depending on that buffer size and the serial BAUD.

...

This is also why you lose the last debug output on a crash... the last debug data is stranded in the serial drivers RX buffer.

Interleaved Output

Because the output is done character at a time, the debug output from different tasks may get multiplexed and unreadable in the most critical of cases. The interleaved output can become totally useless, usually in the most complex situations where you need the debug output the most. Many times my plans to debug a problem with SYSLOG output has been thwarted because the output is just uninterpretable in a highly multitasking context.

Buffer Overrun

The root cause of this problem is the RX buffering in the serial driver: Character output is done one character at a time. That is not usually and issue. But when the system is very busy and he serial RX buffer becomes full, then each character output causes the caller to suspending, waiting for space in the RX buffer. It suspends and is moved to the last the of the FIFO for that priority.

...

Of course, there is no work around for the perverse case where the debug output is generated at a higher rate than can be transferred on the serial port. You are just basically out-of-luck in that case.

Solutions

Serialization Buffer

Some of these asynchrony problems could also be reduced or eliminated if all debug output were buffered in an in-memory FIFO. That buffer would serialize output from diffrent sources: Various tasks and interrupt level logic.

...

Serialization via syslog buffer has been recently implemented in NuttX, this option is enabled with CONFIG_SYSLOG_BUFFER.

Crash Dump

It might even be possible to flush that serialization buffer at the time of the crash. This has ability has not yet been implemented as of the time of this writing.

CONFIG_SYSLOG and the RAMLOG

There is a partial solution for all of these issues when CONFIG_SYSLOG=y. In that case, stdout is not used but instead some custom logic is used that is established by the configuration. Currently that option is only used with the RAMLOG. The RAMLOG actually works very nicely and eliminates most of the above issue (except for the interleaving issue). But the RAMLOG also requires some additional logic to get the debug information out of the RAMLOG. In NSH, you can use the dmesg command to dump the content of the RAMLOG to the NSH console.

...