Add timestamp to dpdk.log

Add timestamp to dpdk.log

[Soumya Muralidhar]

[-- Attachment #1: Type: text/plain, Size: 2737 bytes --]

Hi,

I am looking to add timestamp while logging using rte_openlog_stream<https://grok.gigamon.com:8443/source/s?defs=rte_openlog_stream&project=nfv_master> function where you pass the file pointer as a parameter to this function.
Below is the snippet :


const char *dpdk_log_path<https://grok.gigamon.com:8443/source/s?refs=dpdk_log_path&project=nfv_master> = "/var<https://grok.gigamon.com:8443/source/s?path=/var/&project=nfv_master>/log<https://grok.gigamon.com:8443/source/s?path=/var/log/&project=nfv_master>/dpdk.log<https://grok.gigamon.com:8443/source/s?path=/var/log/dpdk.log&project=nfv_master>"


log_fp<https://grok.gigamon.com:8443/source/xref/nfv_master/src/ehal_lib/ehal_dpdk_binding.c?r=6c10cae5#log_fp> = fopen<https://grok.gigamon.com:8443/source/s?defs=fopen&project=nfv_master>(dpdk_log_path<https://grok.gigamon.com:8443/source/xref/nfv_master/src/ehal_lib/ehal_dpdk_binding.c?r=6c10cae5#dpdk_log_path>, "a+");

    if (log_fp<https://grok.gigamon.com:8443/source/xref/nfv_master/src/ehal_lib/ehal_dpdk_binding.c?r=6c10cae5#log_fp> == NULL<https://grok.gigamon.com:8443/source/s?defs=NULL&project=nfv_master>) {

         EHAL_LOG<https://grok.gigamon.com:8443/source/s?defs=EHAL_LOG&project=nfv_master>(LOG_ERR<https://grok.gigamon.com:8443/source/s?defs=LOG_ERR&project=nfv_master>, "dpdk log file(%s) open failed, error (%d:%s) ",

                  dpdk_log_path<https://grok.gigamon.com:8443/source/xref/nfv_master/src/ehal_lib/ehal_dpdk_binding.c?r=6c10cae5#dpdk_log_path>, errno<https://grok.gigamon.com:8443/source/s?defs=errno&project=nfv_master>, strerror<https://grok.gigamon.com:8443/source/s?defs=strerror&project=nfv_master>(errno<https://grok.gigamon.com:8443/source/s?defs=errno&project=nfv_master>));

         return (errno<https://grok.gigamon.com:8443/source/s?defs=errno&project=nfv_master>);



rte_openlog_stream<https://grok.gigamon.com:8443/source/s?defs=rte_openlog_stream&project=nfv_master>(log_fp<https://grok.gigamon.com:8443/source/xref/nfv_master/src/ehal_lib/ehal_dpdk_binding.c?r=6c10cae5#log_fp>);


Thanks,
Soumya
This message may contain confidential and privileged information. If it has been sent to you in error, please reply to advise the sender of the error and then immediately delete it. If you are not the intended recipient, do not read, copy, disclose or otherwise use this message. The sender disclaims any liability for such unauthorized use. NOTE that all incoming emails sent to Gigamon email accounts will be archived and may be scanned by us and/or by external service providers to detect and prevent threats to our systems, investigate illegal or inappropriate behavior, and/or eliminate unsolicited promotional emails (“spam”).

[-- Attachment #2: Type: text/html, Size: 7532 bytes --]

Re: Add timestamp to dpdk.log

[Stephen Hemminger]

Your message is garbaled with lots of bogus URL's. Please avoid HTML mail
or weird links.

I use this. There was a more general version submitted as a patch to
DPDK but no one seemed interested.  The reason for redirecting stdout
is that are libraries we use that print to stdout and want to get timestamps
from them if debugging startup issues.


/*
 * Sample of redirecting DPDK log stream.
 *
 * If program is run for debugging then stdout will be a console and
 * put messages onto console stream with timestamps.  Otherwise, just
 * put message onto stderr which systemd journal handles.  No need for
 * syslog because that causes duplicate messages.
 */

static struct timespec log_t0; /* Start program in monotonic time */

/*
 * Write message to standard output with timestamp.
 * Use writev() so that timestamp and message do not get interleaved.
 */
static ssize_t
dpdk_log_tty_write(__rte_unused void *ctx, const char *buf, size_t size)
{
	struct timespec ts;
	struct iovec iov[2];
	char tbuf[64];

	/* format up monotonic timestamp */
	clock_gettime(CLOCK_MONOTONIC, &ts);

	ts.tv_sec -= log_t0.tv_sec;
	ts.tv_nsec -= log_t0.tv_nsec;
	if (ts.tv_nsec < 0) {
		--ts.tv_sec;
		ts.tv_nsec += NS_PER_S;
	}

	iov[0].iov_base = tbuf;
	iov[0].iov_len  = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ",
				   ts.tv_sec, ts.tv_nsec / 1000u);

	/* extra cast is workaround to remove const qualifier */
	iov[1].iov_base = (void *)(uintptr_t)buf;
	iov[1].iov_len = size;

	return writev(STDOUT_FILENO, iov, 2);
}

static cookie_io_functions_t dpdk_log_tty_func = {
	.write = dpdk_log_tty_write,
};

/*
 * Print message to stderr with priority format so that 
 * Systemd journal can handle it. Alternative would be
 * to use syslog or use sd_journal; but less is more.
 */
static ssize_t
dpdk_log_write(__rte_unused void *ctx, const char *buf, size_t size)
{
	/* Syslog error levels are from 0 to 7, DPDK uses 1 to 8 */
	int priority = rte_log_cur_msg_loglevel() - 1;

	fprintf(stderr, "<%i>%.*s\n", priority, (int)size, buf);
	return size;
}

static cookie_io_functions_t dpdk_log_func = {
	.write = dpdk_log_write,
};

/*
 * Override default DPDK logging which duplicates messages
 * to both stderr and syslog.
 */
static void log_init(void)
{
	backplane_logtype = rte_log_register("backplane");
	if (backplane_logtype >= 0)
		rte_log_set_level(backplane_logtype, RTE_LOG_INFO);

	if (isatty(STDOUT_FILENO)) {
		clock_gettime(CLOCK_MONOTONIC, &log_t0);

		stdout = fopencookie(NULL, "w+", dpdk_log_tty_func);
		setlinebuf(stdout);
		rte_openlog_stream(stdout);
	} else {
		FILE *jf;

		jf = fopencookie(NULL, "w+", dpdk_log_func);
		rte_openlog_stream(jf);
	}
}

/* Put DPDK log back onto stderr */
static void log_uninit(void)
{
	FILE *logf;

	logf = rte_log_get_stream();
	if (logf != stderr) {
		rte_openlog_stream(stderr);
		fclose(logf);
	}
}

Re: Add timestamp to dpdk.log

[Soumya Muralidhar]

Hi Stephen,

Thanks for getting back. But I am looking at storing logs with timestamps in a file, basically something similar to syslog. Could you help me with that ?

Regards,
Soumya

On 1/5/22, 8:17 AM, "Stephen Hemminger" <stephen@networkplumber.org> wrote:

    WARNING: This email originated from outside of Gigamon. Use caution with any links or attachments.


    Your message is garbaled with lots of bogus URL's. Please avoid HTML mail
    or weird links.

    I use this. There was a more general version submitted as a patch to
    DPDK but no one seemed interested.  The reason for redirecting stdout
    is that are libraries we use that print to stdout and want to get timestamps
    from them if debugging startup issues.


    /*
     * Sample of redirecting DPDK log stream.
     *
     * If program is run for debugging then stdout will be a console and
     * put messages onto console stream with timestamps.  Otherwise, just
     * put message onto stderr which systemd journal handles.  No need for
     * syslog because that causes duplicate messages.
     */

    static struct timespec log_t0; /* Start program in monotonic time */

    /*
     * Write message to standard output with timestamp.
     * Use writev() so that timestamp and message do not get interleaved.
     */
    static ssize_t
    dpdk_log_tty_write(__rte_unused void *ctx, const char *buf, size_t size)
    {
            struct timespec ts;
            struct iovec iov[2];
            char tbuf[64];

            /* format up monotonic timestamp */
            clock_gettime(CLOCK_MONOTONIC, &ts);

            ts.tv_sec -= log_t0.tv_sec;
            ts.tv_nsec -= log_t0.tv_nsec;
            if (ts.tv_nsec < 0) {
                    --ts.tv_sec;
                    ts.tv_nsec += NS_PER_S;
            }

            iov[0].iov_base = tbuf;
            iov[0].iov_len  = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ",
                                       ts.tv_sec, ts.tv_nsec / 1000u);

            /* extra cast is workaround to remove const qualifier */
            iov[1].iov_base = (void *)(uintptr_t)buf;
            iov[1].iov_len = size;

            return writev(STDOUT_FILENO, iov, 2);
    }

    static cookie_io_functions_t dpdk_log_tty_func = {
            .write = dpdk_log_tty_write,
    };

    /*
     * Print message to stderr with priority format so that
     * Systemd journal can handle it. Alternative would be
     * to use syslog or use sd_journal; but less is more.
     */
    static ssize_t
    dpdk_log_write(__rte_unused void *ctx, const char *buf, size_t size)
    {
            /* Syslog error levels are from 0 to 7, DPDK uses 1 to 8 */
            int priority = rte_log_cur_msg_loglevel() - 1;

            fprintf(stderr, "<%i>%.*s\n", priority, (int)size, buf);
            return size;
    }

    static cookie_io_functions_t dpdk_log_func = {
            .write = dpdk_log_write,
    };

    /*
     * Override default DPDK logging which duplicates messages
     * to both stderr and syslog.
     */
    static void log_init(void)
    {
            backplane_logtype = rte_log_register("backplane");
            if (backplane_logtype >= 0)
                    rte_log_set_level(backplane_logtype, RTE_LOG_INFO);

            if (isatty(STDOUT_FILENO)) {
                    clock_gettime(CLOCK_MONOTONIC, &log_t0);

                    stdout = fopencookie(NULL, "w+", dpdk_log_tty_func);
                    setlinebuf(stdout);
                    rte_openlog_stream(stdout);
            } else {
                    FILE *jf;

                    jf = fopencookie(NULL, "w+", dpdk_log_func);
                    rte_openlog_stream(jf);
            }
    }

    /* Put DPDK log back onto stderr */
    static void log_uninit(void)
    {
            FILE *logf;

            logf = rte_log_get_stream();
            if (logf != stderr) {
                    rte_openlog_stream(stderr);
                    fclose(logf);
            }
    }

This message may contain confidential and privileged information. If it has been sent to you in error, please reply to advise the sender of the error and then immediately delete it. If you are not the intended recipient, do not read, copy, disclose or otherwise use this message. The sender disclaims any liability for such unauthorized use. NOTE that all incoming emails sent to Gigamon email accounts will be archived and may be scanned by us and/or by external service providers to detect and prevent threats to our systems, investigate illegal or inappropriate behavior, and/or eliminate unsolicited promotional emails (“spam”).

Re: Add timestamp to dpdk.log

[Stephen Hemminger]

On Wed, 5 Jan 2022 17:42:49 +0000
Soumya Muralidhar <soumya.muralidhar@gigamon.com> wrote:

> Hi Stephen,
> 
> Thanks for getting back. But I am looking at storing logs with timestamps in a file, basically something similar to syslog. Could you help me with that ?
> 
> Regards,
> Soumya
> 
> On 1/5/22, 8:17 AM, "Stephen Hemminger" <stephen@networkplumber.org> wrote:
> 
>     WARNING: This email originated from outside of Gigamon. Use caution with any links or attachments.
> 
> 
>     Your message is garbaled with lots of bogus URL's. Please avoid HTML mail
>     or weird links.
> 
>     I use this. There was a more general version submitted as a patch to
>     DPDK but no one seemed interested.  The reason for redirecting stdout
>     is that are libraries we use that print to stdout and want to get timestamps
>     from them if debugging startup issues.
> 
> 
>     /*
>      * Sample of redirecting DPDK log stream.
>      *
>      * If program is run for debugging then stdout will be a console and
>      * put messages onto console stream with timestamps.  Otherwise, just
>      * put message onto stderr which systemd journal handles.  No need for
>      * syslog because that causes duplicate messages.
>      */
> 
>     static struct timespec log_t0; /* Start program in monotonic time */
> 
>     /*
>      * Write message to standard output with timestamp.
>      * Use writev() so that timestamp and message do not get interleaved.
>      */
>     static ssize_t
>     dpdk_log_tty_write(__rte_unused void *ctx, const char *buf, size_t size)
>     {
>             struct timespec ts;
>             struct iovec iov[2];
>             char tbuf[64];
> 
>             /* format up monotonic timestamp */
>             clock_gettime(CLOCK_MONOTONIC, &ts);
> 
>             ts.tv_sec -= log_t0.tv_sec;
>             ts.tv_nsec -= log_t0.tv_nsec;
>             if (ts.tv_nsec < 0) {
>                     --ts.tv_sec;
>                     ts.tv_nsec += NS_PER_S;
>             }
> 
>             iov[0].iov_base = tbuf;
>             iov[0].iov_len  = snprintf(tbuf, sizeof(tbuf), "[%8lu.%06lu] ",
>                                        ts.tv_sec, ts.tv_nsec / 1000u);
> 
>             /* extra cast is workaround to remove const qualifier */
>             iov[1].iov_base = (void *)(uintptr_t)buf;
>             iov[1].iov_len = size;
> 
>             return writev(STDOUT_FILENO, iov, 2);
>     }
> 
>     static cookie_io_functions_t dpdk_log_tty_func = {
>             .write = dpdk_log_tty_write,
>     };
> 
>     /*
>      * Print message to stderr with priority format so that
>      * Systemd journal can handle it. Alternative would be
>      * to use syslog or use sd_journal; but less is more.
>      */
>     static ssize_t
>     dpdk_log_write(__rte_unused void *ctx, const char *buf, size_t size)
>     {
>             /* Syslog error levels are from 0 to 7, DPDK uses 1 to 8 */
>             int priority = rte_log_cur_msg_loglevel() - 1;
> 
>             fprintf(stderr, "<%i>%.*s\n", priority, (int)size, buf);
>             return size;
>     }
> 
>     static cookie_io_functions_t dpdk_log_func = {
>             .write = dpdk_log_write,
>     };
> 
>     /*
>      * Override default DPDK logging which duplicates messages
>      * to both stderr and syslog.
>      */
>     static void log_init(void)
>     {
>             backplane_logtype = rte_log_register("backplane");
>             if (backplane_logtype >= 0)
>                     rte_log_set_level(backplane_logtype, RTE_LOG_INFO);
> 
>             if (isatty(STDOUT_FILENO)) {
>                     clock_gettime(CLOCK_MONOTONIC, &log_t0);
> 
>                     stdout = fopencookie(NULL, "w+", dpdk_log_tty_func);
>                     setlinebuf(stdout);
>                     rte_openlog_stream(stdout);
>             } else {
>                     FILE *jf;
> 
>                     jf = fopencookie(NULL, "w+", dpdk_log_func);
>                     rte_openlog_stream(jf);
>             }
>     }
> 
>     /* Put DPDK log back onto stderr */
>     static void log_uninit(void)
>     {
>             FILE *logf;
> 
>             logf = rte_log_get_stream();
>             if (logf != stderr) {
>                     rte_openlog_stream(stderr);
>                     fclose(logf);
>             }
>     }
> 
> This message may contain confidential and privileged information. If it has been sent to you in error, please reply to advise the sender of the error and then immediately delete it. If you are not the intended recipient, do not read, copy, disclose or otherwise use this message. The sender disclaims any liability for such unauthorized use. NOTE that all incoming emails sent to Gigamon email accounts will be archived and may be scanned by us and/or by external service providers to detect and prevent threats to our systems, investigate illegal or inappropriate behavior, and/or eliminate unsolicited promotional emails (“spam”).

Just use my example and make code like dpdk_tty_log_write that does writev to your file.