Network logging overhaul #8816

jukkar · 2018-07-09T15:51:07Z

This PR converts the CONFIG_NET_DEBUG_* and CONFIG_SYS_LOG_NET_LEVEL options to just simple CONFIG_NET_*_LOG_LEVEL setting. This enables user to have more fine grained debugging. The code uses the new logging subsystem for logging.

jukkar · 2018-07-09T15:53:01Z

@nordic-krch If you have time, please review and check if it makes sense what I am doing when converting to new logger.

nashif · 2018-07-09T15:56:51Z

drivers/ethernet/eth_native_posix.c

@@ -208,7 +207,7 @@ static int eth_send(struct net_if *iface, struct net_pkt *pkt)

 	update_gptp(iface, pkt, true);

-	SYS_LOG_DBG("Send pkt %p len %d", pkt, count);
+	NET_DBG("Send pkt %p len %d", pkt, count);


why is NET_DBG required? Why not use LOG_DBG directly?

I had some issues when using logger directly. I will revisit this in next version.

codecov-io · 2018-07-09T16:26:44Z

Codecov Report

Merging #8816 into master will decrease coverage by 0.33%.
The diff coverage is 57.89%.

@@            Coverage Diff            @@
##           master   #8816      +/-   ##
=========================================
- Coverage   53.24%   52.9%   -0.34%     
=========================================
  Files         209     210       +1     
  Lines       25630   25732     +102     
  Branches     5537    5672     +135     
=========================================
- Hits        13647   13614      -33     
- Misses       9787    9802      +15     
- Partials     2196    2316     +120

Impacted Files	Coverage Δ
subsys/net/ip/nbr.c	`84.61% <ø> (-7.06%)`	⬇️
subsys/net/lib/coap/coap_link_format.c	`15.74% <ø> (ø)`	⬆️
subsys/net/ip/promiscuous.c	`54.83% <ø> (ø)`	⬆️
subsys/net/ip/net_if.c	`65.49% <ø> (+0.74%)`	⬆️
subsys/net/l2/dummy/dummy.c	`100% <ø> (ø)`	⬆️
subsys/net/lib/sockets/sockets.c	`41.56% <ø> (ø)`	⬆️
subsys/net/ip/ipv6_mld.c	`50.38% <ø> (-0.8%)`	⬇️
subsys/net/ip/ipv6_fragment.c	`27.41% <ø> (-0.98%)`	⬇️
subsys/net/ip/nbr.h	`0% <ø> (ø)`	⬆️
drivers/ethernet/eth_native_posix_adapt.c	`39.62% <ø> (ø)`	⬆️
... and 81 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 65477b7...bac1bd7. Read the comment docs.

mike-scott · 2018-07-09T17:35:01Z

Is this PR setting a precedent? Will every subsystem in Zephyr eventually convert from using CONFIG_SYS_LOG_* options to CONFIG_LOG_*? I feel like this PR changes the net subsystem from one set of snowflake configs.. to another set.

nashif · 2018-07-10T13:11:30Z

Is this PR setting a precedent? Will every subsystem in Zephyr eventually convert from using CONFIG_SYS_LOG_* options to CONFIG_LOG_*? I feel like this PR changes the net subsystem from one set of snowflake configs.. to another set.

yes, we will move to the new logging subsystem, not sure if much though has been put in migration from the old to the new, i.e. I would have been happy if we kept CONFIG_SYS_LOG and just changed the implementation beneath it but the issue is that there are more changes needed, it is not a 1:1 translation.

Transition path based on what we have now: keep sys_log working, move to LOG everywhere, obsolete sys_log later.

jukkar · 2018-07-10T13:19:05Z

New version uploaded. I made the patches a bit more fine grained. @mike-scott I separated the lwm2m changes to two separate patches if you want to handle them separately or do not want them to be merged.

About the new logger, I made a trivial and simplified test with frdm-k64f and ping.

New logger but no debug options enabled:

ping -c 64 192.0.2.1
PING 192.0.2.1 (192.0.2.1) 56(84) bytes of data.
64 bytes from 192.0.2.1: icmp_seq=1 ttl=64 time=0.602 ms
64 bytes from 192.0.2.1: icmp_seq=2 ttl=64 time=0.257 ms

Then same thing with new logger but various networking debug options enabled, like core, icmpv4, context etc

ping -c 64 192.0.2.1
PING 192.0.2.1 (192.0.2.1) 56(84) bytes of data.
64 bytes from 192.0.2.1: icmp_seq=1 ttl=64 time=0.409 ms
64 bytes from 192.0.2.1: icmp_seq=2 ttl=64 time=0.226 ms
64 bytes from 192.0.2.1: icmp_seq=3 ttl=64 time=0.211 ms

so basically no difference in execution between these two.

Then a control run with old logging and same debug options enabled as in previous run.

ping -c 64 192.0.2.1
PING 192.0.2.1 (192.0.2.1) 56(84) bytes of data.
64 bytes from 192.0.2.1: icmp_seq=1 ttl=64 time=85.0 ms
64 bytes from 192.0.2.1: icmp_seq=2 ttl=64 time=55.3 ms

pizi-nordic

General comment:
Soon we will have a console, which will be fully integrated with logger (#8872). To fully utilize capabilities of new logging subsystem I suggest the following:

Keep some hierarchy module names. The dynamic log management will allow you to do something like this "log enable net_tcp_*".
If something could be instantiated multiple times, please consider using LOG_INST*. Then you will be able to filter logs from given instance(s).

pizi-nordic · 2018-07-12T12:49:58Z

drivers/net/Kconfig

-	int
-	prompt "SLIP driver log level"
-	depends on SYS_LOG && SLIP
+config	SLIP_LOG_LEVEL


Could we have a choice here instead of numeric value?

I briefly looked about this and it is not possible to do things like this
default y if NET_LOG_LEVEL > 3
in Kconfig if we use choice fields.

We could have template like:
choice
prompt "Module logging level"

config MODULE_LOG_LEVEL_OFF
bool "Off"
config MODULE_LOG_LEVEL_ERR
bool "Error"
config MODULE_LOG_LEVEL_WRN
bool "Warning"
config MODULE_LOG_LEVEL_INF
bool "Info"
config MODULE_LOG_LEVEL_DBG
bool "Debug"
endchoice

config MODULE_LOG_LEVEL
int
default 0 if MODULE_LOG_LEVEL_OFF
default 1 if MODULE_LOG_LEVEL_ERR
default 2 if MODULE_LOG_LEVEL_WRN
default 3 if MODULE_LOG_LEVEL_INF
default 4 if MODULE_LOG_LEVEL_DBG

@ulfalizer is it possible to have some kind of templates in kconfig. As you can see in above comment, ideally we should have common scheme for configuring logging in modules.

pizi-nordic · 2018-07-12T12:52:36Z

drivers/net/slip.c

@@ -63,7 +66,7 @@ struct slip_context {
 #endif
 };

-#if SYS_LOG_LEVEL >= SYS_LOG_LEVEL_DEBUG
+#if LOG_LEVEL >= LOG_LEVEL_DBG
 #if defined(CONFIG_SYS_LOG_SHOW_COLOR)


Is #if defined(CONFIG_SYS_LOG_SHOW_COLOR) still valid?

The hexdump routine in slip.c needs conversion to use logger hexdump. The color check will disappear when that conversion is done.

pizi-nordic · 2018-07-12T12:58:43Z

include/logging/log.h

@@ -280,6 +280,39 @@ int log_printk(const char *fmt, va_list ap);
 #endif /*CONFIG_LOG_RUNTIME_FILTERING*/

 #else /* LOG enabled for the module. */
+/* No logging, so set the macros to do nothing */


I think, that this is not needed after recent changes in logger.

@jukkar, ping. This commit ("logging: Avoid compile error if debug prints are disabled") should not be part of this PR (should be its own PR, merged long ago, or maybe no longer needed).

pizi-nordic · 2018-07-12T13:00:48Z

include/net/net_core.h

+
+LOG_MODULE_REGISTER();
+
+#define NET_DBG(fmt, ...) LOG_DBG("(%p): %s: " fmt, k_current_get(), \


What about "(%p): %s(): " ?

Omitting () from function name saves two characters without sacrificing any readability. I am not sure about the print format atm, this is what we currently print with sys_log, but of course we could change that when printing with logger.

pizi-nordic · 2018-07-12T13:01:27Z

include/net/net_ip.h

@@ -229,7 +229,7 @@ enum net_addr_type {
 	NET_ADDR_OVERRIDABLE,
 };

-#if NET_LOG_ENABLED > 0


I think we should use LOG_* constants instead of numeric values.

You don't need this ifdef at all. Function is used only in NET_DBG(). When debug level is off, compiler will not include this function.

pizi-nordic · 2018-07-12T13:01:34Z

include/net/net_pkt.h

@@ -687,7 +687,7 @@ static inline void net_pkt_set_src_ipv6_addr(struct net_pkt *pkt)
 	NET_BUF_POOL_DEFINE(name, count, CONFIG_NET_BUF_DATA_SIZE,	\
 			    CONFIG_NET_BUF_USER_DATA_SIZE, NULL)

-#if defined(CONFIG_NET_DEBUG_NET_PKT)
+#if CONFIG_NET_LOG_LEVEL_NET_PKT > 3


I think we should use LOG_* constants instead of numeric values.

And probably use >= comparison for clarity. ("Logging starts at the level X", not "logging starts after the level Y".)

pizi-nordic · 2018-07-12T13:04:32Z

include/net/net_core.h

-#ifndef NET_SYS_LOG_LEVEL
-#define SYS_LOG_LEVEL CONFIG_SYS_LOG_NET_LEVEL
+#if !defined(LOG_LEVEL)
+#if defined(NET_LOG_LEVEL)


Why we need NET_LOG_LEVEL? Could we just use per-module LOG_LEVEL?

This was done like this so that networking header files can have network specific checks.
For example if LOG_LEVEL is used, it might turn on things in network header files even if networking is disabled.

mike-scott · 2018-07-12T17:55:10Z

subsys/net/lib/lwm2m/ipso_light_control.c

-#define SYS_LOG_LEVEL CONFIG_SYS_LOG_LWM2M_LEVEL
-#include <logging/sys_log.h>
+#define LOG_MODULE_NAME ipso_light_control
+#define LOG_LEVEL CONFIG_SYS_LOG_LWM2M_LEVEL


Do we want to change the Kconfig naming here to NET_LOG_LWM2M_LEVEL to match the rest of the subsys/net/lib options?

Hmm, I think I will leave to you to decide. I will remove the lwm2m patches from this PR, you can re-use them if you wish.

mike-scott · 2018-07-12T17:56:13Z

samples/net/echo_server/src/echo-server.c

-#define NET_LOG_ENABLED 1
-#endif
+#define LOG_MODULE_NAME echo_server
+#define NET_LOG_LEVEL 4


Why switch to a hard coded 4 here?

Why switch to a hard coded 4 here?

I guess it is one-to-one translation. Was:

#define NET_SYS_LOG_LEVEL SYS_LOG_LEVEL_DEBUG

now:

#define NET_LOG_LEVEL 4

Except, as mentioned by @pizi-nordic, should used symbolic constants everywhere.

mike-scott · 2018-07-12T17:56:51Z

samples/net/echo_server/src/tcp.c

-#define NET_LOG_ENABLED 1
-#endif
+#define LOG_MODULE_NAME echo_server_tcp
+#define NET_LOG_LEVEL LOG_LEVEL_DBG


Almost all of the samples are using SYS_LOG_LEVEL_DEBUG elsewhere in the PR. Should we be using LOG_LEVEL_DBG (like here) instead?

pfalcon · 2018-07-17T13:39:24Z

subsys/net/Kconfig.hostname

-	default n
+config  NET_LOG_LEVEL_HOSTNAME
+	int "Debug level hostname configuration"
+	default 0


Why we have "default 0" here (and "default 1" in other places). Default level should be ERROR (if not WARNING) consistently, to make sure that by default, errors don't go unnoticed by user.

pfalcon · 2018-07-17T13:44:49Z

This PR converts the CONFIG_NET_DEBUG_* and CONFIG_SYS_LOG_NET_LEVEL ...

This PR converts the networking also to use new logging system

And this is very well-known and well-discussed mistakes, which yet continues to happen - please don't pack too much stuff into one PR. I'm peering for half an hour into this, and don't understand much. Sure, after I'll peer into this for a couple hours more, I'll understand more than that, but why that should be required?

pfalcon · 2018-07-17T13:45:16Z

Conflicting files
include/logging/log.h
subsys/net/Kconfig.hostname

Please rebase, this can't be applied to master to try it.

pfalcon · 2018-07-17T13:48:34Z

This PR converts the CONFIG_NET_DEBUG_* and CONFIG_SYS_LOG_NET_LEVEL options to just simple CONFIG_NET_LOG_LEVEL_* setting. This enables user to have more fine grained debugging.

I guess this needs more detailed explanation, mentioning CONFIG_NET_LOG_LEVEL_MAX and CONFIG_NET_LOG_LEVEL_DEFAULT, and with specific examples: before it was , now instead you do .

pfalcon · 2018-07-17T13:53:15Z

subsys/net/lib/config/Kconfig

-	default n
-	default y if NET_LOG_GLOBAL
+config NET_LOG_LEVEL_CONFIG
+	int "Debug level net config library"


Should be "Log level for net config library". Similarly in many other places.

pfalcon · 2018-07-17T13:56:48Z

samples/net/echo_server/src/echo-server.c

@@ -131,6 +128,13 @@ void main(void)
 		start_udp();
 	}

+	while (1) {


This of course can't be in the code ready for merging.

pfalcon

At least following should be done:

Rebase.
Don't use values like 0,1,2,3,4, use symbolic logging levels instead.
Debug logging help texts should look well in English.

Also ideally, converting to new logger should be split into different PR from switching to "snowflake" debug config. But my guess that's not possible (well, practical) at this stage.

P.S. As the new logger is an impeding doom, I'm all for getting over it, but we can't push sloppy conversion in just to get over it.

nordic-krch · 2018-07-17T15:58:11Z

@jukkar regarding

I think we should use LOG_* constants instead of numeric values.

Isn't it because LOG_LEVEL_... defines are in log.h file which must be included by C file because it utilizing defines? If so then I will move those defines to other file (something like log_types.h).

nordic-krch · 2018-07-17T15:58:33Z

@jukkar

nordic-krch · 2018-07-17T16:02:05Z

@jukkar accident close/reopen sequence.

Once #8704 was merged you can clean up examples and remove explicit log processing and initialization and rely on implicit logger handling (option CONFIG_LOG_PROCESS_THREAD must be enabled)

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

Add "openthread" tag for sanitychecker when it is running OpenThread specific tests. This way it is easier to run just those few OpenThread specific tests. Signed-off-by: Jukka Rissanen <[email protected]>

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

One parameter was missing when calling net_hexdump_frags() which caused compile error. Signed-off-by: Jukka Rissanen <[email protected]>

Convert the USB networking to use the new logging system. Signed-off-by: Jukka Rissanen <[email protected]>

Use new logging system instead of SYS_LOG. Signed-off-by: Jukka Rissanen <[email protected]>

The code was trying to print peer IP address string but that pointer could contain garbage. There is actually no need to print anything in this case, the error code return is enough. Signed-off-by: Jukka Rissanen <[email protected]>

The application won't work anymore as it uses the old syslog logging and networking is now converted to use the new logger so there is no need for this sample application. Signed-off-by: Jukka Rissanen <[email protected]>

As the debugging print calls are async, all the strings that might be overwritten must use log_strdup() which will create a copy of the printable string. Signed-off-by: Jukka Rissanen <[email protected]>

jukkar · 2018-10-03T10:09:15Z

Fixed sanity errors.
Added spaces around = when sourcing Kconfig template file

jukkar · 2018-10-04T10:07:04Z

ping @nordic-krch can you recheck and +1 if ok

edit: fixed typos

nordic-krch

@jukkar i've been on sick leave thus the delay. looks ok.

jukkar · 2018-10-04T11:13:47Z

i've been on sick leave thus the delay. looks ok.

No worries, thanks for the review!

pfalcon · 2018-10-05T11:28:26Z

Added spaces around = when sourcing Kconfig template file

For reference, I don't see that being changed, e.g. not even where I made a comment on that https://github.com/zephyrproject-rtos/zephyr/pull/8816/files#r221893651 (but there're more occurrences). Let me submit a ticket to clarify the style we should use.

jukkar added area: Networking area: Logging DNM This PR should not be merged (Do Not Merge) labels Jul 9, 2018

jukkar requested review from mike-scott, pfalcon, rveerama1 and tbursztyka as code owners July 9, 2018 15:51

jukkar requested a review from nordic-krch July 9, 2018 15:51

nashif reviewed Jul 9, 2018

View reviewed changes

pizi-nordic self-requested a review July 10, 2018 11:00

jukkar force-pushed the net-logging branch from 252f6e0 to 1195a91 Compare July 10, 2018 13:12

pizi-nordic reviewed Jul 12, 2018

View reviewed changes

mike-scott suggested changes Jul 12, 2018

View reviewed changes

pfalcon reviewed Jul 17, 2018

View reviewed changes

pfalcon previously requested changes Jul 17, 2018

View reviewed changes

nordic-krch closed this Jul 17, 2018

nordic-krch reopened this Jul 17, 2018

jukkar added 20 commits October 3, 2018 13:07

samples: net: ws_echo_server: Convert to new logging system

add4c3c

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: zperf: Convert to new logging system

24fd866

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: sntp: Convert to new logging system

b29f52d

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: lldp: Convert to new logging system

018c203

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: nats: Convert to new logging system

f555309

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: rpl_border_router: Convert to new logging system

d526eaf

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: rpl_node: Convert to new logging system

14dd246

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: mqtt_publisher: Convert to new logging system

4413b9d

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: wpan_serial: Convert to new logging system

bca88e1

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: wpanusb: Convert to new logging system

91c6ec7

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: echo-*: Add openthread tag for sanitychecker

8709a24

Add "openthread" tag for sanitychecker when it is running OpenThread specific tests. This way it is easier to run just those few OpenThread specific tests. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: leds_demo: Convert to new logging system

4f578e5

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

tests: net: Convert to new logging system

e34e2a1

Use new logging system with support for network log level. Signed-off-by: Jukka Rissanen <[email protected]>

usb: Fix net_hexdump_frags() parameters

cc8f870

One parameter was missing when calling net_hexdump_frags() which caused compile error. Signed-off-by: Jukka Rissanen <[email protected]>

usb: net: Convert to use new logging

b872a6e

Convert the USB networking to use the new logging system. Signed-off-by: Jukka Rissanen <[email protected]>

net: lwm2m: Convert to new logging system

515b085

Use new logging system instead of SYS_LOG. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: lwm2m_client: Convert to new logging system

3fde014

Use new logging system instead of SYS_LOG. Signed-off-by: Jukka Rissanen <[email protected]>

samples: net: syslog: Remove the sample application

f6cae40

The application won't work anymore as it uses the old syslog logging and networking is now converted to use the new logger so there is no need for this sample application. Signed-off-by: Jukka Rissanen <[email protected]>

net: Use log_strdup() when printing debug strings

bac1bd7

As the debugging print calls are async, all the strings that might be overwritten must use log_strdup() which will create a copy of the printable string. Signed-off-by: Jukka Rissanen <[email protected]>

jukkar force-pushed the net-logging branch from 54a9954 to bac1bd7 Compare October 3, 2018 10:07

nordic-krch approved these changes Oct 4, 2018

View reviewed changes

jukkar merged commit 57a8db7 into zephyrproject-rtos:master Oct 4, 2018

jukkar deleted the net-logging branch October 4, 2018 11:14

pfalcon mentioned this pull request Oct 5, 2018

Clarification of the code style to use for module* params in Kconfig templates #10404

Closed

nordic-krch mentioned this pull request Oct 31, 2018

[RFC] logging: Default to redirecting printk() through it #10715

Closed


		LOG_MODULE_REGISTER();

		#define NET_DBG(fmt, ...) LOG_DBG("(%p): %s: " fmt, k_current_get(), \

Network logging overhaul #8816

Network logging overhaul #8816

Uh oh!

Conversation

jukkar commented Jul 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jukkar commented Jul 9, 2018

Uh oh!

nashif Jul 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

codecov-io commented Jul 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

mike-scott commented Jul 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nashif commented Jul 10, 2018

Uh oh!

jukkar commented Jul 10, 2018

Uh oh!

pizi-nordic left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pfalcon commented Jul 17, 2018

Uh oh!

pfalcon commented Jul 17, 2018

Uh oh!

pfalcon commented Jul 17, 2018

Uh oh!

jukkar commented Jul 9, 2018 •

edited

Loading

nashif Jul 9, 2018 •

edited

Loading

codecov-io commented Jul 9, 2018 •

edited

Loading

mike-scott commented Jul 9, 2018 •

edited

Loading

pizi-nordic left a comment •

edited

Loading

jukkar commented Oct 4, 2018 •

edited

Loading