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 08:01:29 -0800
Message-ID: <20171219080129.0af9ab42@xeon-e3>
References: <96F900E1-45E4-4448-A876-5EC2B92E7E8D@intel.com>
 <20171219074427.2f6f4dfe@xeon-e3>
 <98763630-51EB-440B-934C-8489563F3AA2@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-pl0-f68.google.com (mail-pl0-f68.google.com
 [209.85.160.68]) by dpdk.org (Postfix) with ESMTP id 202AF2C18
 for <dev@dpdk.org>; Tue, 19 Dec 2017 17:01:34 +0100 (CET)
Received: by mail-pl0-f68.google.com with SMTP id s3so7203090plp.4
 for <dev@dpdk.org>; Tue, 19 Dec 2017 08:01:34 -0800 (PST)
In-Reply-To: <98763630-51EB-440B-934C-8489563F3AA2@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 15:51:09 +0000
"Wiles, Keith" <keith.wiles@intel.com> wrote:

> > On Dec 19, 2017, at 9:44 AM, Stephen Hemminger <stephen@networkplumber.=
org> wrote:
> >=20
> > On Tue, 19 Dec 2017 14:12:27 +0000
> > "Wiles, Keith" <keith.wiles@intel.com> wrote:
> >  =20
> >> Hi all,
> >>=20
> >> One other area with logging is we do not time stamp our logs to the sc=
reen, 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.
> >>=20
> >> I would like to see more information in the log output with file and l=
ine 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 messa=
ge=20
> >> [  14.039999] 49203 pkt_data_to_mbuf(pkt_mbufs.h:85)    FNET: Failed a=
ppend to mbuf too much data.
> >>=20
> >> - 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 fi=
xed width.
> >> - Function/file/line number __func__(basename(__FILE__):__LINE__) usin=
g 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 origina=
l log 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=
 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.
> >>=20
> >> What are your thoughts here?
> >>=20
> >> Regards,
> >> Keith
> >>  =20
> >=20
> > Syslog is where most real applications send their logging, and it alrea=
dy does
> > timestamping. =20
>=20
> Yes, I agree I forgot to add it was optional. The log messages currently =
go the screen for me and I still need to see the timestamp instead of looki=
ng in a log file.
>=20
> Regards,
> Keith
>=20

Applications are also free to implement their own log output handler.
Why not do that if you need something special.