net-related logging: Don't see the expected output + crash in logging

[pfalcon]

Context: I'm developing a new network driver. I never wrote one from scratch, so doing a lot of stupid things. I would think that logging is there to help me, but instead, it puzzles me.

So, to reproduce this one, you'd need to look at the branch https://github.com/pfalcon/zephyr/tree/smsc9220-pfalcon-logging-issue . There lives the new WIP driver, and to test it, I made adhoc prj.conf changes to hello_world and echo_server samples. The changes are largely the same and include CONFIG_ETHERNET_LOG_LEVEL_DBG=y. I run:

hello_world$ zephyr-make BOARD=mps2_an385 run
[QEMU] CPU: cortex-m3
init ok
eth_smsc9220_isr: 0 0
eth_initialize
eth_tx
eth_tx
***** Booting Zephyr OS zephyr-v1.13.0-1494-gfabf4596e1 *****
[00:00:00.000,000] <err> eth_smsc9220.eth_init: MAC 52:54:00:12:34:56
Hello World! mps2_an385

That's the expected output (specifically <err> logging).

Now I run:

echo_server$ zephyr-make BOARD=mps2_an385 run
[QEMU] CPU: cortex-m3


uart:~$ init ok
eth_smsc9220_isr: 0 0
eth_initialize
eth_tx
eth_tx
***** Booting Zephyr OS zephyr-v1.13.0-1494-gfabf4596e1 *****
eth_tx

Which is not the expected output, as I miss that err logging of mac address.

(If you run these samples, you'll notice that soon after that output, they crash. Well, that's the issue I'd like logging to help me with, and not sure if it can, because from my PoV it works erratically even with simpler things.)

[pfalcon]

Also cc: @jukkar. Because you see, stuff works as expected in completely unrelated, barebones sample. And doesn't work with a proper networking sample, where one would expect everything work without a hitch. One could imagine that it's some bad interaction with networking logging.

[pfalcon]

So, to reproduce this one, you'd need to look at the branch https://github.com/pfalcon/zephyr/tree/smsc9220-pfalcon

Ok, as that branch is actually for feature development, I created https://github.com/pfalcon/zephyr/tree/smsc9220-pfalcon-logging-issue to serve just for reproducing of the issue described here (will edit link in the description too).

[pfalcon]

UPDATE: This crash is fixed in master.

Not creating another ticket for the following close issue:

Apply following patch:

diff --git a/samples/hello_world/prj.conf b/samples/hello_world/prj.conf
index 469078a972..a155e49139 100644
--- a/samples/hello_world/prj.conf
+++ b/samples/hello_world/prj.conf
@@ -9,3 +9,6 @@ CONFIG_ETH_SMSC9220=y
 
 CONFIG_LOG=y
 CONFIG_ETHERNET_LOG_LEVEL_DBG=y
+
+CONFIG_NET_LOG=y
+CONFIG_NET_DEFAULT_LOG_LEVEL_DBG=y

Then:

samples/hello_world$ zephyr-make BOARD=mps2_an385 run
...
To exit from QEMU enter: 'CTRL+a, x'
[QEMU] CPU: cortex-m3
init ok
eth_smsc9220_isr: 0 0
eth_initialize
***** MPU FAULT *****
  Data Access Violation
  MMFAR Address: 0x0
***** Hardware exception *****
Current thread ID = 0x20000ee8
Faulting instruction address = 0x13b8
Fatal fault in essential thread! Spinning...

0x13b8 is in log_msg_create_n.

So, whatever happens, I don't expect logging to crash my app, there're enough ways it can crash without it ;-).

[pfalcon]

0x13b8 is in log_msg_create_n.

Heh, nevermind, appears to be fixed in master.

[pfalcon]

But the original issue from the description still holds with 2d78259

Actually, with that master, I would expect echo_server to log:

[00:00:00.000,000] <err> net_if.net_if_up: {assert: 'net_if_get_link_addr(iface)->addr != NULL' failed}

But it doesn't. (hello_world does)

[pfalcon]

But the original issue from the description still holds with 2d78259

smsc9220-pfalcon-logging-issue branch has now been rebased on that master.

[nordic-krch]

@pfalcon, tried to reproduce but got following Cmake error:

kconfiglib.KconfigError: 
drivers/ethernet/Kconfig:35: 'drivers/ethernet/Kconfig.smsc9220' does not exist.

[pfalcon]

@nordic-krch: D'oh! Pushed that file.

[nordic-krch]

@pfalcon i tried to reproduce, i'm getting following output:

[0/1] To exit from QEMU enter: 'CTRL+a, x'[QEMU] CPU: cortex-m3
init ok
eth_smsc9220_isr: 0 0
eth_initialize
eth_tx
eth_tx
***** Booting Zephyr OS zephyr-v1.13.0-1612-ga3345d16c4 *****
[00:00:00.000,000] <err> eth_smsc9220.eth_init: MAC 52:54:00:12:34:56
Hello World! mps2_an385
qemu: fatal: Lockup: can't escalate 3 to HardFault (current priority -1)

R00=0000002a R01=200066b0 R02=0000a5b1 R03=00000000
R04=200066d0 R05=00000000 R06=00000929 R07=200066b0
R08=00000000 R09=ffffffff R10=00000000 R11=00000000
R12=00000000 R13=20006664 R14=00000a3f R15=00000000
XPSR=00000003 ---- A handler
FPSCR: 00000000
Aborted (core dumped)
FAILED: zephyr/CMakeFiles/run 
cd /home/user/zephyr/samples/hello_world/build && /home/user/Tools/zephyr-sdk/sysroots/x86_64-pokysdk-linux/usr/bin/qemu-system-arm -cpu cortex-m3 -machine mps2-an385 -nographic -vga none -pidfile qemu.pid -serial mon:stdio -kernel /home/user/zephyr/samples/hello_world/build/zephyr/zephyr.elf

Is this wrong?

One thing that i noticed is that after quitting qemu im no longer able to use terminal, it does not accept any new characters. Have you seen something like that? I'm running terminal on mint 19

[pfalcon]

@nordic-krch , ok you tried "hello_world", and that's correct, expected output.

Now please try net/echo_server, and there's no

<err> eth_smsc9220.eth_init: MAC 52:54:00:12:34:56

line output, even though the settings are seemingly similar. (Well, they are definitely the same for me as a user.)

[pfalcon]

One thing that i noticed is that after quitting qemu im no longer able to use terminal, it does not accept any new characters. Have you seen something like that? I'm running terminal on mint 19

Sure, I get that every day ;-). tty is in raw/no-echo mode. just type "reset" blindly. (may need twice, if you already typed something before).

[nordic-krch]

ok, reproduced. #10734 fixes it. It's ready to be merged.

[pfalcon]

Thanks!