MYNEWT-262 Log module needs split in logging and reporting

[Vipul Rahane <vi...@runtime.io>]

Hello,

I am currently looking at:
MYNEWT-262 <https://issues.apache.org/jira/browse/MYNEWT-262> Log module needs split in logging and reporting

My understanding of the problem is as follows:
- We do not have a way to re-register a log(Change handlers of modules) currently. The application should be able to override handlers for different logs.

Solution is to do the following:

- Make changes to the log_register() function to take LOG_MODULE_X as an argument. This module ID is present as a field in the log structure and can be used anytime an entry is logged in the specific log. There was a disconnect earlier as the log itself did not quite have a module ID of it’s own. If we want to be able to filter logs the module ID needs to be used as a filtering criteria to pick the right log node from the queue.

- Also, various MACROs such as LOG_INFO, LOG_DEBUG, LOG_WARN, etc require the module ID to be passed as an argument which is not necessary as the log structure itself contains the module ID.

- The log_append() function would not need the module ID to be passed as an argument to it.

- Add a function log_set_handler(handler) to set handlers for all the modules to the same one.

- When newtmgr requests to read all the logs using “logs show” command, the response would contain a module ID as well. If the response does not contain any entries, no response would be sent for that log. Module ID also helps in filtering the log entries while sending the response.

JSON Response:

{
	"rc": 0,
	"logs": [{
		"name": "log",
		"module": 0,
		"type": 1,
		"entries": [{
			"msg": "GPIO toggle from 1 to 0",
			"ts": 1007000,
			"level": 2,
			"index": 1
		}, {
			"msg": "GPIO toggle from 0 to 1",
			"ts": 2015000,
			"level": 2,
			"index": 2
		}, {
			"msg": "GPIO toggle from 1 to 0",
			"ts": 3019000,
			"level": 2,
			"index": 3
		}, {
			"msg": "GPIO toggle from 0 to 1",
			"ts": 4024000,
			"level": 2,
			"index": 4
		}]
	}]
}

When the log_set_handler() function is called in the app, it makes all the function pointers if any nodes exist in the TAILQ to point to the same log handlers. One problem with this approach is that since the log_set_handler() function needs to be called after all the modules are initialized, logging to the same log during initialization is not possible as the logs are not created at that point.

Ways to solve this:
1. Passing the log handler as an argument to all the init functions which I don’t like personally as it is not too clean.

2. Having a global default log handler which gets set by calling log_set_handler() which would take precedence over other logs as log_register() would also look at this default handler and if the default handler is present, the log infrastructure decides to use that instead of whats specified in the modules. As a result everything that gets logged would go to the log defined by the app including initialization logs.

Thoughts ?

Regards,
Vipul Rahane

Re: MYNEWT-262 Log module needs split in logging and reporting

[Christopher Collins <cc...@apache.org>]

Hi Vipul,

On Mon, Apr 18, 2016 at 11:53:28PM -0700, Vipul Rahane wrote:
> - Make changes to the log_register() function to take LOG_MODULE_X as
> an argument. This module ID is present as a field in the log structure
> and can be used anytime an entry is logged in the specific log. There
> was a disconnect earlier as the log itself did not quite have a module
> ID of it’s own. If we want to be able to filter logs the module ID
> needs to be used as a filtering criteria to pick the right log node
> from the queue.

Sounds good to me.  Currently, a log has a name but not a module ID, and
there is no way to determine which log created a particular log entry.

[...]

> - When newtmgr requests to read all the logs using “logs show”
> command, the response would contain a module ID as well. If the
> response does not contain any entries, no response would be sent for
> that log. Module ID also helps in filtering the log entries while
> sending the response.
> 
> JSON Response:
> 
> {
> 	"rc": 0,
> 	"logs": [{
> 		"name": "log",
> 		"module": 0,
> 		"type": 1,
> 		"entries": [{
> 			"msg": "GPIO toggle from 1 to 0",
> 			"ts": 1007000,
> 			"level": 2,
> 			"index": 1
> 		}, {
> 			"msg": "GPIO toggle from 0 to 1",
> 			"ts": 2015000,
> 			"level": 2,
> 			"index": 2
> 		}, {
> 			"msg": "GPIO toggle from 1 to 0",
> 			"ts": 3019000,
> 			"level": 2,
> 			"index": 3
> 		}, {
> 			"msg": "GPIO toggle from 0 to 1",
> 			"ts": 4024000,
> 			"level": 2,
> 			"index": 4
> 		}]
> 	}]
> }

I don't necessarily disagree, but I am wondering why the newtmgr user
needs to know about module IDs at all.  I was thinking module IDs were
only used internally to keep track of which log a particular entry
belongs to.  It seems like the newtmgr user would rather just deal with
log names than module IDs.

That said, I am not against providing extra information to the user if
it might be helpful.

> When the log_set_handler() function is called in the app, it makes all
> the function pointers if any nodes exist in the TAILQ to point to the
> same log handlers. One problem with this approach is that since the
> log_set_handler() function needs to be called after all the modules
> are initialized, logging to the same log during initialization is not
> possible as the logs are not created at that point.
> 
> Ways to solve this:
> 1. Passing the log handler as an argument to all the init functions
> which I don’t like personally as it is not too clean.
> 
> 2. Having a global default log handler which gets set by calling
> log_set_handler() which would take precedence over other logs as
> log_register() would also look at this default handler and if the
> default handler is present, the log infrastructure decides to use that
> instead of whats specified in the modules. As a result everything that
> gets logged would go to the log defined by the app including
> initialization logs.
> 
> Thoughts ?

As background for other readers: libraries are responsible for fully
configuring their own logs, including specifying where the log writes to
(e.g., console, a particular flash circular buffer, etc.).  This is
problematic because the library doesn't know the app's capabilities and
requirements; it is the app which should have the final say regarding
where each log gets written.

I think we need to make sure the following requirements are met (this is
off the top of my head, so feel free to call me out if I'm saying
something absurd!):

A. An app can easily arrange for all logs to be written to the same
place.

B. An app can specify where a particular library's log(s) get written
to.

Requirement A allows for easy bringup and debugging.  Requirement B is
necessary for production firmware where each log is expected to use a
particular handler.  I think your solution 2 addresses requirement A,
but it does not give an app sufficient control to implement requirement
B.

To give a hypothetical example: an app wants to log all bluetooth
activity to flash circular buffer x, and all application activity to
flash circular buffer y.  The app is not interested in logs from any
other libraries, so it has not reserved any RAM or flash to hold these
other logs.  A default handler won't meet this app's requirements
for two reasons: 1) only a single circular buffer gets used, but the app
wants to use two, and 2) logs from all libraries get written to flash,
but the app wants to save the flash space for the logs that it actually
cares about.

I can't think of any way to give an app the control it needs, except by
implementing your first solution (library logging is configured during
initialization).  I think combining both solutions would be good; the
application can just set the default handler during early development,
and it can use more fine-grained configuration in production code.

Thanks,
Chris