From mboxrd@z Thu Jan  1 00:00:00 1970
From: Stephen Hemminger <stephen@networkplumber.org>
Subject: Re: Logging format and time stamping
Date: Tue, 19 Dec 2017 07:44:27 -0800
Message-ID: <20171219074427.2f6f4dfe@xeon-e3>
References: <96F900E1-45E4-4448-A876-5EC2B92E7E8D@intel.com>
Mime-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable
Cc: DPDK <dev@dpdk.org>
To: "Wiles, Keith" <keith.wiles@intel.com>
Return-path: <dev-bounces@dpdk.org>
Received: from mail-pg0-f43.google.com (mail-pg0-f43.google.com [74.125.83.43])
 by dpdk.org (Postfix) with ESMTP id 89975160
 for <dev@dpdk.org>; Tue, 19 Dec 2017 16:44:30 +0100 (CET)
Received: by mail-pg0-f43.google.com with SMTP id k15so10677512pgr.7
 for <dev@dpdk.org>; Tue, 19 Dec 2017 07:44:30 -0800 (PST)
In-Reply-To: <96F900E1-45E4-4448-A876-5EC2B92E7E8D@intel.com>
List-Id: DPDK patches and discussions <dev.dpdk.org>
List-Unsubscribe: <https://dpdk.org/ml/options/dev>,
 <mailto:dev-request@dpdk.org?subject=unsubscribe>
List-Archive: <http://dpdk.org/ml/archives/dev/>
List-Post: <mailto:dev@dpdk.org>
List-Help: <mailto:dev-request@dpdk.org?subject=help>
List-Subscribe: <https://dpdk.org/ml/listinfo/dev>,
 <mailto:dev-request@dpdk.org?subject=subscribe>
Errors-To: dev-bounces@dpdk.org
Sender: "dev" <dev-bounces@dpdk.org>

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

> Hi all,
>=20
> One other area with logging is we do not time stamp our logs to the scree=
n, which I feel is needed in some cases. The bigger area is figuring out wh=
ere the log message came from and greping the code is a bit hard in some ca=
ses.
>=20
> 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.
>=20
> [timestamp] pid function_name(filename:line) logid: log message
>=20
>=20
> [ timestamp ] pid   Function/file/line number           Lid: Log message=
=20
> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed appe=
nd to mbuf too much data.
>=20
> - The time stamp is from gettimeofday seconds.usecs formatted. Using a re=
lative 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, =E2=80=A6) and then the original l=
og message.
>=20
> 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 lc=
ore created the message. The bigger one is the function/file/line is the on=
e a would like to see most. Making some of the fields fixed length helps al=
ign the messages.
>=20
> What are your thoughts here?
>=20
> Regards,
> Keith
>=20

Syslog is where most real applications send their logging, and it already d=
oes
timestamping.