[dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Montorsi, Francesco]

Hi all,
I've not been following closely latest DPDK activity but my company is using DPDK and we recently upgraded to 16.07. 
We apply several patches to DPDK sources, to make it more similar to a "standard library" (currently it is quite intrusive: calls abort() at will, writes its own log, etc etc)... I think that it may be useful to give back to the community some of these (small) "enhancements".

One of them is about logging: as the application where we embed DPDK already has its log file, we want DPDK to log in our log facility framework. 
My "fix" is simple: I just put a callback function in RTE logging system that, by default, points to the existing rte_vlog() function. If needed the library user can provide its own callback function to do what he likes.

The attached patch is what we use right now. I totally understand it needs some rework to put it in a better shape... but first of all: are you interested in such patch? 

Thanks,
Francesco Montorsi

Re: [dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Olivier Matz]

Hi Francesco,

On 10/04/2016 12:24 PM, Montorsi, Francesco wrote:
> Hi all,
> I've not been following closely latest DPDK activity but my company is using DPDK and we recently upgraded to 16.07. 
> We apply several patches to DPDK sources, to make it more similar to a "standard library" (currently it is quite intrusive: calls abort() at will, writes its own log, etc etc)... I think that it may be useful to give back to the community some of these (small) "enhancements".
> 
> One of them is about logging: as the application where we embed DPDK already has its log file, we want DPDK to log in our log facility framework. 
> My "fix" is simple: I just put a callback function in RTE logging system that, by default, points to the existing rte_vlog() function. If needed the library user can provide its own callback function to do what he likes.
> 
> The attached patch is what we use right now. I totally understand it needs some rework to put it in a better shape... but first of all: are you interested in such patch? 

It seems the mailing list stripped your patch sent as attachment.
Can you please resend it again in the body of the mail?

I think we can already redirect logs to a file by using fopencookie() +
rte_openlog_stream(). Did you already check these functions?

Regards,
Olivier

Re: [dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Montorsi, Francesco]

Hi Olivier,

> It seems the mailing list stripped your patch sent as attachment.
> Can you please resend it again in the body of the mail?
You're right sorry. It's attached at the end of this mail.

> I think we can already redirect logs to a file by using fopencookie() +
> rte_openlog_stream(). Did you already check these functions?

Yes, but to be honest, that seems a troublesome solution for something as easy as logging a string; e.g. by using fopencookie() approach, you don't have the concept of "log message", you just provide a function that must write a block of bytes somewhere.  Typically instead, you need to know where a log message starts and ends, to e.g., add prefixes/postfixes to it.

Indeed, most of the C/C++ (open source) libraries have some simple hook that allows the user to have more control on logging... I think DPDK should be no exception... :)

Thanks,
Francesco



>From 52d4fdccee4de3787e85589ff8f666028ad9ea7b Mon Sep 17 00:00:00 2001
From: Francesco Montorsi <fmontorsi@empirix.com>
Date: Tue, 4 Oct 2016 12:08:34 +0200
Subject: [PATCH] Enable custom log sink implementations

---
 lib/librte_eal/common/eal_common_log.c          | 23 ++++++++++++++++++++---
 lib/librte_eal/common/include/rte_log.h         |  8 ++++++--
 lib/librte_eal/linuxapp/eal/eal_debug.c         | 16 ++++++++++++++--
 lib/librte_eal/linuxapp/eal/rte_eal_version.map |  2 +-
 4 files changed, 41 insertions(+), 8 deletions(-)

diff --git a/lib/librte_eal/common/eal_common_log.c b/lib/librte_eal/common/eal_common_log.c
index 967991a..5e86309 100644
--- a/lib/librte_eal/common/eal_common_log.c
+++ b/lib/librte_eal/common/eal_common_log.c
@@ -41,15 +41,25 @@
 
 #include "eal_private.h"
 
+
+/* forward declaration */
+int
+rte_vlog_to_FILE(uint32_t level, uint32_t logtype, const char *formattedstr);
+
 /* global log structure */
 struct rte_logs rte_logs = {
 	.type = ~0,
 	.level = RTE_LOG_DEBUG,
 	.file = NULL,
+	.log_callback = rte_vlog_to_FILE
 };
 
 static FILE *default_log_stream;
 
+#define LOG_BUFFER_SIZE			4095
+static char log_buffer[LOG_BUFFER_SIZE+1];
+
+
 /**
  * This global structure stores some informations about the message
  * that is currently beeing processed by one lcore
@@ -123,7 +133,7 @@ int rte_log_cur_msg_logtype(void)
  * defined by the previous call to rte_openlog_stream().
  */
 int
-rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
+rte_vlog_to_FILE(uint32_t level, uint32_t logtype, const char *formattedstr)
 {
 	int ret;
 	FILE *f = rte_logs.file;
@@ -135,11 +145,16 @@ rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
 	RTE_PER_LCORE(log_cur_msg).loglevel = level;
 	RTE_PER_LCORE(log_cur_msg).logtype = logtype;
 
-	ret = vfprintf(f, format, ap);
+	ret = fprintf(f, "%s", formattedstr);
 	fflush(f);
 	return ret;
 }
 
+void rte_set_custom_vlog(rte_vlog_func_t callback)
+{
+	rte_logs.log_callback = callback;
+}
+
 /*
  * Generates a log message The message will be sent in the stream
  * defined by the previous call to rte_openlog_stream().
@@ -152,8 +167,10 @@ rte_log(uint32_t level, uint32_t logtype, const char *format, ...)
 	int ret;
 
 	va_start(ap, format);
-	ret = rte_vlog(level, logtype, format, ap);
+	vsnprintf(log_buffer, LOG_BUFFER_SIZE, format, ap);
 	va_end(ap);
+
+	ret = rte_logs.log_callback(level, logtype, log_buffer);
 	return ret;
 }
 
diff --git a/lib/librte_eal/common/include/rte_log.h b/lib/librte_eal/common/include/rte_log.h
index 919563c..3dcb135 100644
--- a/lib/librte_eal/common/include/rte_log.h
+++ b/lib/librte_eal/common/include/rte_log.h
@@ -50,11 +50,15 @@ extern "C" {
 #include <stdio.h>
 #include <stdarg.h>
 
+/** The backend used for logging. Can be user-defined. */
+typedef int (*rte_vlog_func_t)(uint32_t level, uint32_t logtype, const char *formattedstr);
+
 /** The rte_log structure. */
 struct rte_logs {
 	uint32_t type;  /**< Bitfield with enabled logs. */
 	uint32_t level; /**< Log level. */
 	FILE *file;     /**< Pointer to current FILE* for logs. */
+	rte_vlog_func_t log_callback;
 };
 
 /** Global log informations */
@@ -236,8 +240,8 @@ int rte_log(uint32_t level, uint32_t logtype, const char *format, ...)
  *   - 0: Success.
  *   - Negative on error.
  */
-int rte_vlog(uint32_t level, uint32_t logtype, const char *format, va_list ap)
-	__attribute__((format(printf,3,0)));
+void rte_set_custom_vlog(rte_vlog_func_t callback);
+
 
 /**
  * Generates a log message.
diff --git a/lib/librte_eal/linuxapp/eal/eal_debug.c b/lib/librte_eal/linuxapp/eal/eal_debug.c
index 5fbc17c..f411d96 100644
--- a/lib/librte_eal/linuxapp/eal/eal_debug.c
+++ b/lib/librte_eal/linuxapp/eal/eal_debug.c
@@ -78,9 +78,16 @@ void __rte_panic(const char *funcname, const char *format, ...)
 	va_list ap;
 
 	rte_log(RTE_LOG_CRIT, RTE_LOGTYPE_EAL, "PANIC in %s():\n", funcname);
+
+#define LOG_BUFFER_SIZE			4095
+static char log_buffer[LOG_BUFFER_SIZE+1];
+
 	va_start(ap, format);
-	rte_vlog(RTE_LOG_CRIT, RTE_LOGTYPE_EAL, format, ap);
+	vsnprintf(log_buffer, LOG_BUFFER_SIZE, format, ap);
 	va_end(ap);
+
+	rte_logs.log_callback(RTE_LOG_CRIT, RTE_LOGTYPE_EAL, log_buffer);
+
 	rte_dump_stack();
 	rte_dump_registers();
 	abort();
@@ -99,10 +106,15 @@ rte_exit(int exit_code, const char *format, ...)
 		RTE_LOG(CRIT, EAL, "Error - exiting with code: %d\n"
 				"  Cause: ", exit_code);
 
+#define LOG_BUFFER_SIZE			4095
+static char log_buffer[LOG_BUFFER_SIZE+1];
+
 	va_start(ap, format);
-	rte_vlog(RTE_LOG_CRIT, RTE_LOGTYPE_EAL, format, ap);
+	vsnprintf(log_buffer, LOG_BUFFER_SIZE, format, ap);
 	va_end(ap);
 
+	rte_logs.log_callback(RTE_LOG_CRIT, RTE_LOGTYPE_EAL, log_buffer);
+
 #ifndef RTE_EAL_ALWAYS_PANIC_ON_ERROR
 	exit(exit_code);
 #else
diff --git a/lib/librte_eal/linuxapp/eal/rte_eal_version.map b/lib/librte_eal/linuxapp/eal/rte_eal_version.map
index 83721ba..b35c8c3 100644
--- a/lib/librte_eal/linuxapp/eal/rte_eal_version.map
+++ b/lib/librte_eal/linuxapp/eal/rte_eal_version.map
@@ -94,6 +94,7 @@ DPDK_2.0 {
 	rte_openlog_stream;
 	rte_realloc;
 	rte_set_application_usage_hook;
+	rte_set_custom_vlog;
 	rte_set_log_level;
 	rte_set_log_type;
 	rte_socket_id;
@@ -102,7 +103,6 @@ DPDK_2.0 {
 	rte_sys_gettid;
 	rte_thread_get_affinity;
 	rte_thread_set_affinity;
-	rte_vlog;
 	rte_xen_dom0_memory_attach;
 	rte_xen_dom0_memory_init;
 	rte_zmalloc;
-- 
2.7.4

Re: [dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Olivier Matz]

Hi Francesco,

On 10/04/2016 02:28 PM, Montorsi, Francesco wrote:
> Hi Olivier,
> 
>> It seems the mailing list stripped your patch sent as attachment. 
>> Can you please resend it again in the body of the mail?
> You're right sorry. It's attached at the end of this mail.
> 
>> I think we can already redirect logs to a file by using
>> fopencookie() + rte_openlog_stream(). Did you already check these
>> functions?
> 
> Yes, but to be honest, that seems a troublesome solution for
> something as easy as logging a string; e.g. by using fopencookie()
> approach, you don't have the concept of "log message", you just
> provide a function that must write a block of bytes somewhere.
> Typically instead, you need to know where a log message starts and
> ends, to e.g., add prefixes/postfixes to it.

I'm not sure that true if you call setbuf(log_stream, NULL).

In that case, it looks easy to prefix / postfix messages with a
fopencookie callback like:

/* example on stdout */
ssize_t
simple_write(void *c, const char *buf, size_t size)
{
	ssize_t ret1, ret2, ret3;

	ret1 = fwrite("<", 1, 1, stdout);
	if (ret1 == 0)
		return 0;
	ret2 = fwrite(buf, size, 1, stdout);
	if (ret2 == 0)
		return 0;
	ret3 = fwrite(">", 1, 1, stdout);
	if (ret3 == 0)
		return 0;
	return ret1 + ret2 + ret3;
}


> Indeed, most of the C/C++ (open source) libraries have some simple
> hook that allows the user to have more control on logging... I think
> DPDK should be no exception... :)

I understand that the current API is a bit more complex, but I don't
feel there is any blocking issue to do what you want. What do you think?


Also, I know you've said your patch needs some rework, but as you've
also said you are using it, maybe it would be useful for you to know:
- it makes use of a global variable 'log_buffer', shared by all the
pthreads, which can lead to crashes
- it strips the log messages to 4095 chars

Regards,
Olivier

Re: [dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Montorsi, Francesco]

Hi Olivier,

> On 10/04/2016 02:28 PM, Montorsi, Francesco wrote:
> > Yes, but to be honest, that seems a troublesome solution for something
> > as easy as logging a string; e.g. by using fopencookie() approach, you
> > don't have the concept of "log message", you just provide a function
> > that must write a block of bytes somewhere.
> > Typically instead, you need to know where a log message starts and
> > ends, to e.g., add prefixes/postfixes to it.
> 
> I'm not sure that true if you call setbuf(log_stream, NULL).
> 
> In that case, it looks easy to prefix / postfix messages with a fopencookie
> callback like:
> 
> /* example on stdout */
> ssize_t
> simple_write(void *c, const char *buf, size_t size) {
> 	ssize_t ret1, ret2, ret3;
> 
> 	ret1 = fwrite("<", 1, 1, stdout);
> 	if (ret1 == 0)
> 		return 0;
> 	ret2 = fwrite(buf, size, 1, stdout);
> 	if (ret2 == 0)
> 		return 0;
> 	ret3 = fwrite(">", 1, 1, stdout);
> 	if (ret3 == 0)
> 		return 0;
> 	return ret1 + ret2 + ret3;
> }
> 
I didn't know about setbuf()... but are we sure that in this way the simple_write() function will always receive a full string? I mean: in the manpage for setbuf() it says:

"... When the first I/O operation occurs on a file, malloc(3) is called, and a buffer is obtained. .... If the argument buf is NULL, only the mode is affected; a new buffer will be allocated on the next read or write operation."

But: is it true that 1 write operation corresponds to 1 vfprintf() call? Maybe if you have a "long" a single vfprintf() call may translate to several simple_write() calls... I don't know honestly.

> > Indeed, most of the C/C++ (open source) libraries have some simple
> > hook that allows the user to have more control on logging... I think
> > DPDK should be no exception... :)
> 
> I understand that the current API is a bit more complex, but I don't feel there
> is any blocking issue to do what you want. What do you think?

See above. Moreover, IMHO it would be much more user-friendly to have a simple function callback to implement vs having to dig into fopencookie()+setbuf()+etc etc . 

> Also, I know you've said your patch needs some rework, but as you've also
> said you are using it, maybe it would be useful for you to know:
> - it makes use of a global variable 'log_buffer', shared by all the pthreads,
> which can lead to crashes

That's a good point. I will turn it into a __thread variable. Thanks for pointing out this.

> - it strips the log messages to 4095 chars

Correct, but in my experience DPDK never creates such a long line of log message... 

Francesco

Re: [dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Olivier Matz]

Hi Francesco,

On 10/05/2016 03:26 PM, Montorsi, Francesco wrote:
> Hi Olivier,
> 
>> On 10/04/2016 02:28 PM, Montorsi, Francesco wrote:
>>> Yes, but to be honest, that seems a troublesome solution for something
>>> as easy as logging a string; e.g. by using fopencookie() approach, you
>>> don't have the concept of "log message", you just provide a function
>>> that must write a block of bytes somewhere.
>>> Typically instead, you need to know where a log message starts and
>>> ends, to e.g., add prefixes/postfixes to it.
>>
>> I'm not sure that true if you call setbuf(log_stream, NULL).
>>
>> In that case, it looks easy to prefix / postfix messages with a fopencookie
>> callback like:
>>
>> /* example on stdout */
>> ssize_t
>> simple_write(void *c, const char *buf, size_t size) {
>> 	ssize_t ret1, ret2, ret3;
>>
>> 	ret1 = fwrite("<", 1, 1, stdout);
>> 	if (ret1 == 0)
>> 		return 0;
>> 	ret2 = fwrite(buf, size, 1, stdout);
>> 	if (ret2 == 0)
>> 		return 0;
>> 	ret3 = fwrite(">", 1, 1, stdout);
>> 	if (ret3 == 0)
>> 		return 0;
>> 	return ret1 + ret2 + ret3;
>> }
>>
> I didn't know about setbuf()... but are we sure that in this way the simple_write() function will always receive a full string? I mean: in the manpage for setbuf() it says:
> 
> "... When the first I/O operation occurs on a file, malloc(3) is called, and a buffer is obtained. .... If the argument buf is NULL, only the mode is affected; a new buffer will be allocated on the next read or write operation."
> 
> But: is it true that 1 write operation corresponds to 1 vfprintf() call? Maybe if you have a "long" a single vfprintf() call may translate to several simple_write() calls... I don't know honestly.

I did a quick test with a fixed version of simple_write():

ssize_t
simple_write(void *c, const char *buf, size_t size)
{
	ssize_t ret1 = -42, ret3 = -42;
	ssize_t ret = 0;

	ret1 = fwrite("<", 1, 1, stdout);
	if (ret1 == 0)
		goto ret;
	ret = fwrite(buf, 1, size, stdout);
	if (ret != size)
		goto ret;
	ret3 = fwrite(">", 1, 1, stdout);
	if (ret3 == 0)
		goto ret;

ret:
	/* printf("ret=%d ret1=%d ret3=%d\n", (int)ret, (int)ret1, (int)ret3); */
	return ret;
}


It looks like transmitting a string bigger than BUFSIZ (8192) induces
several calls to simple_write(). For smaller calls, it seems there is no
split (1 printf = 1 simple_write).

Of course, this is a just test and not a proof :)
I think we would have a similar issue with the other approach.

For me, the current API looks ok, however let's see the opinion of the
maintainer that could be different of mine. In any case, thank you for
proposing enhancements.

Regards,
Olivier

Re: [dpdk-dev] Proposal: enable redirection of DPDK logs from the user app

[Matthew Hall]

On Wed, Oct 05, 2016 at 01:26:30PM +0000, Montorsi, Francesco wrote:
> Correct, but in my experience DPDK never creates such a long line of log message... 
> 
> Francesco

This comment is fatally flawed. Many of us write our applications using these 
functions. I have things which hex-dump packets when certain debug levels are 
enabled. Sadly my patch to add deeper levels to default DPDK was rejected, but 
with that I have very detailed levels that say everything I ever do to the 
packet.

Matthew.