Re: [dpdk-dev] Logging format and time stamping

[Stephen Hemminger <stephen@networkplumber.org>]

On Tue, 19 Dec 2017 14:12:27 +0000
"Wiles, Keith" <keith.wiles@intel.com> wrote:

> Hi all,
> 
> One other area with logging is we do not time stamp our logs to the screen, which I feel is needed in some cases. The bigger area is figuring out where the log message came from and greping the code is a bit hard in some cases.
> 
> I would like to see more information in the log output with file and line number of the log message with the time stamp. e.g.
> 
> [timestamp] pid function_name(filename:line) logid: log message
> 
> 
> [ timestamp ] pid   Function/file/line number           Lid: Log message 
> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed append to mbuf too much data.
> 
> - The time stamp is from gettimeofday seconds.usecs formatted. Using a relative time from application start.
> - The pid is the process ID or logical core id in fixed %5d or some fixed width.
> - Function/file/line number __func__(basename(__FILE__):__LINE__) using a fixed width like %30s does not work in all cases but most.
> - The lid is the LOG ID used(PMD, EAL, …) and then the original log message.
> 
> The timestamp helps determine when the message was created, but could be turned off for normal use. The pid would be nice to know which thread or lcore created the message. The bigger one is the function/file/line is the one a would like to see most. Making some of the fields fixed length helps align the messages.
> 
> What are your thoughts here?
> 
> Regards,
> Keith
> 

Syslog is where most real applications send their logging, and it already does
timestamping.