Logging with CONFIG_LOG_IMMEDIATE=y from ISR leads to assert

[pfalcon]

This was initially reported in meta-issue #11655 (comment) , using a WIP PR #11680 . It's a hope that #12406 would address this. But as it's still in flux, and #11680 seemed to be blocked by this issue, I proceeded to investigate to make sure it's known how to reproduce it to ensure fixing.

So, turns out that if CONFIG_LOG_INPLACE_PROCESS=y is enabled (which currently does not work per expectations, but I enabled it nonetheless, hoping to alleviate at least some issues with deferred processing), then logging from ISR leads to assert failure, if CONFIG_ASSERT is enabled, or to a lockup otherwise.

Assert messages seen are (independently):

ASSERTION FAIL [!_IsInIsr() || timeout == 0] @ /home/pfalcon/projects-3rdparty/Embedded/Zephyr/zephyr/kernel/msg_q.c:113
ASSERTION FAIL [!(_kernel.nested != 0U) || timeout == 0] @ /home/pfalcon/projects-3rdparty/Embedded/Zephyr/zephyr/kernel/msg_4

(the last line is cut, due to a way QEMU configures terminal)

I was able to reproduce this using following patch:

diff --git a/drivers/ethernet/eth_e1000.c b/drivers/ethernet/eth_e1000.c
index c3da959edd..a5445497bf 100644
--- a/drivers/ethernet/eth_e1000.c
+++ b/drivers/ethernet/eth_e1000.c
@@ -129,7 +129,8 @@ static void e1000_isr(struct device *device)
 		icr &= ~ICR_RXO;
 
 		if (pkt) {
-			net_recv_data(dev->iface, pkt);
+			int res = net_recv_data(dev->iface, pkt);
+			if (res < 0) LOG_ERR("net_recv_data: %d", res);
 		} else {
 			eth_stats_update_errors_rx(dev->iface);
 		}
diff --git a/samples/net/echo_server/overlay-e1000.conf b/samples/net/echo_server/overlay-e1000.conf
index 9834ff564d..a7911bb202 100644
--- a/samples/net/echo_server/overlay-e1000.conf
+++ b/samples/net/echo_server/overlay-e1000.conf
@@ -7,4 +7,6 @@ CONFIG_PCI_ENUMERATION=y
 CONFIG_PCI=y
 
 #CONFIG_PCI_DEBUG=y
-#CONFIG_ETHERNET_LOG_LEVEL_DBG=y
+CONFIG_ETHERNET_LOG_LEVEL_DBG=y
+CONFIG_ASSERT=y
+CONFIG_LOG_INPLACE_PROCESS=y

Then running samples/net/echo_server with params:

make BOARD=qemu_x86 CONF_FILE="prj.conf overlay-e1000.conf" run

(Which also requires net-setup.sh from net-tools), then ping 192.0.2.1.

[carlescufi]

@pfalcon I think it's best to get #12406 merged and then all those issues should go away automatically

[carlescufi]

@pfalcon #12406 is now merged, can you verify if this is addressed?

[nordic-krch]

#12327 needs to merge because example uses shell.

[nordic-krch]

this should be fixed now. @pfalcon can you confirm and close?

[pfalcon]

this should be fixed now. @pfalcon can you confirm and close?

Please leave me some time for that, I'm in the middle of other things. Will try to do during this week though.

[nashif]

@pfalcon ping

[pfalcon]

I'm working on other things and couldn't verify this so far. But I can confirm that CONFIG_LOG_IMMEDIATE itself (under normal, non-ISR conditions) now seems to work as expected. Can make bets how long it will take to make that default ;-).

[pfalcon]

So, I proceeded to test this, just to find out that the eth_smsc911x.c driver which on which the issue was reproduced, is broken in the master: https://github.com/zephyrproject-rtos/zephyr/pull/12989/files#r256461904 , with tests which were supposed to keep it from breakage, removed from master either. So, this all will take much more time.

[nordic-krch]

@pfalcon any news here. I would expect that it should work now.

[pfalcon]

Ok, let me close it, will reopen if spot again.