stm32: g0b1re: LOG (& probably shell) not functional if both CONFIG_PM & CONFIG_SHELL are enabled

[ycsin]

Describe the bug
At least the logging subsys won't work if both CONFIG_SHELL and CONFIG_PM are enabled. Im not sure about shell, since the UART doesn't work when MCU entered STOP mode.

To Reproduce
Compile the following on nucleo_g0b1re

main.c:

#include <zephyr.h>

#include <logging/log.h>
LOG_MODULE_REGISTER(main, 4);

void main(void)
{
	while(1) {
		LOG_INF("Hello World! %s", CONFIG_BOARD);
		printk("printk! %s\r\n", CONFIG_BOARD);
		k_sleep(K_SECONDS(2));
	}
}

prj.conf

CONFIG_LOG=y
CONFIG_SHELL=y
CONFIG_PM=y

Log Console output, notice that there's also some seemingly garbage data between the "p" and the "rintk!...", they are actually the color code + the uart:~$ from the shell (so shell could be working?):

*** Booting Zephyr OS build v2.7.0-rc3-156-gb55cd9bc77d7  ***
printk! nucleo_g0b1re
pintk! nucleo_g0b1re
p[rintk! nucleo_g0b1re
pmrintk! nucleo_g0b1re
rintk! nucleo_g0b1re
p
 rintk! nucleo_g0b1re
rintk! nucleo_g0b1re
p
 rintk! nucleo_g0b1re
pintk! nucleo_g0b1re
p[rintk! nucleo_g0b1re
p1rintk! nucleo_g0b1re
p;rintk! nucleo_g0b1re
p3rintk! nucleo_g0b1re
p2rintk! nucleo_g0b1re
pmrintk! nucleo_g0b1re

If I compile without CONFIG_SHELL, prj.conf:

CONFIG_LOG=y
CONFIG_PM=y

Log output:

*** Booting Zephyr OS build v2.7.0-rc3-156-gb55cd9bc77d7  ***
printk! nucleo_g0b1re
[00:00:00.005,000] <inf> main: Hello World! nucleo_g0b1re
printk! nucleo_g0b1re
[00:00:02.007,000] <inf> main: Hello World! nucleo_g0b1re
printk! nucleo_g0b1re
[00:00:04.009,000] <inf> main: Hello World! nucleo_g0b1re
printk! nucleo_g0b1re
[00:00:06.011,000] <inf> main: Hello World! nucleo_g0b1re
printk! nucleo_g0b1re
[00:00:08.013,000] <inf> main: Hello World! nucleo_g0b1re
printk! nucleo_g0b1re
[00:00:10.016,000] <inf> main: Hello World! nucleo_g0b1re
printk! nucleo_g0b1re

If I compile without CONFIG_PM, prj.conf:

CONFIG_LOG=y
CONFIG_SHELL=y

Log output:

*** Booting Zephyr OS build v2.7.0-rc3-156-gb55cd9bc77d7  ***
printk! nucleo_g0b1re


[00:00:00.006,000] <inf> main: Hello World! nucleo_g0b1re
uart:~$ printk! nucleo_g0b1re
[00:00:02.008,000] <inf> main: Hello World! nucleo_g0b1re
uart:~$ printk! nucleo_g0b1re
[00:00:04.010,000] <inf> main: Hello World! nucleo_g0b1re
uart:~$ printk! nucleo_g0b1re
[00:00:06.012,000] <inf> main: Hello World! nucleo_g0b1re
uart:~$ printk! nucleo_g0b1re
[00:00:08.014,000] <inf> main: Hello World! nucleo_g0b1re
uart:~$ printk! nucleo_g0b1re
[00:00:10.016,000] <inf> main: Hello World! nucleo_g0b1re
uart:~$ printk! nucleo_g0b1re

Impact
Harder to debug without LOG.

Environment (please complete the following information):

• win10
• gnuarmemb
• 0e1ecb3

[ycsin]

@erwango ^^

[erwango]

@ycsin Thanks for reporting this.

About the issue title: "stm32: g0b1re: LOG (& probably shell) won't work if CONFIG_PM=y"
From what I can see PM + LOG is working correctly. Can you confirm ?

About SHELL, per nature, using SHELL with PM requires to be able to wake up the SoC thought UART RX,
which is not implemented right now.
So for now status is that it's not supported with PM=y (at least on STM32 platforms).

[ycsin]

From what I can see PM + LOG is working correctly. Can you confirm ?

Yes.

About SHELL, per nature, using SHELL with PM requires to be able to wake up the SoC thought UART RX,
which is not implemented right now.

I'm aware of the uart wkup isn't supported right now.

When the shell works, it should always print uart:~$ at the bottom of the console. Notice that in the first log output that I've posted, there's no uart:~$ at the bottom; instead, each of the control char: [ 1 ; 3 2 m ... and u a r t : ~ $ prompt are scattered among each printks. Due to this anomaly, I'm not sure if the shell "works".

[erwango]

From what I can see PM + LOG is working correctly. Can you confirm ?

Yes.

Then can you rename as :
stm32: g0b1re: SHELL not functional if CONFIG_LOG=y & CONFIG_PM=y ?

About SHELL, per nature, using SHELL with PM requires to be able to wake up the SoC thought UART RX,
which is not implemented right now.

I'm aware of the uart wkup isn't supported right now.

When the shell works, it should always print uart:~$ at the bottom of the console. Notice that in the first log output that I've posted, there's no uart:~$ at the bottom; instead, each of the control char: [ 1 ; 3 2 m ... and u a r t : ~ $ prompt are scattered among each printks. Due to this anomaly, I'm not sure if the shell "works".

[ycsin]

Then can you rename as :
stm32: g0b1re: SHELL not functional if CONFIG_LOG=y & CONFIG_PM=y ?

But LOG subsys doesn't work when prj.conf:

CONFIG_SHELL=y
CONFIG_LOG=y
CONFIG_PM=y

See my first "Log" (console) output, the "[00:00:00.005,000] main: Hello World! nucleo_g0b1re" isn't being printed.

I've edited the title to: "stm32: g0b1re: LOG (& probably shell) not functional if both CONFIG_PM & CONFIG_SHELL are enabled"

[erwango]

See my first "Log" (console) output, the "[00:00:00.005,000] main: Hello World! nucleo_g0b1re" isn't being printed.

Well, I can see "[00:00:00.006,000] main: Hello World! nucleo_g0b1re", and log messages printed every 2 sec. It seems pretty close to me.

[ycsin]

Well, I can see "[00:00:00.006,000] main: Hello World! nucleo_g0b1re", and log messages printed every 2 sec. It seems pretty close to me.

[erwango]

Well, I can see "[00:00:00.006,000] main: Hello World! nucleo_g0b1re", and log messages printed every 2 sec. It seems pretty close to me.

Ok, so that's PM + SHELL + LOG.
My opint was about PM + LOG.
But that's ok, you changed the issue title and that's not clearer, thanks.

[ycsin]

you changed the issue title and that's not clearer

Is that a typo? If not I can change the title to something better?

[erwango]

you changed the issue title and that's not clearer

Is that a typo? If not I can change the title to something better?

:-), typo sorry. This is surely clearer!

[ycsin]

#39128 might be related as well?

[nordic-krch]

One possibility is that printk and shell uart are competing for UART peripheral. Shell uart backend is using interrupt driven API and printk is using uart_poll_out. I'm not sure how well that is supported by the uart driver. At least on nordic uart_poll_out is implemented in a way that it can coexist with interrupt driven API (one can preempt each other).
You can try disabling interrupt driven API in shell: SHELL_BACKEND_SERIAL_INTERRUPT_DRIVEN=n and see if that changes anything.

[cfriedt]

@ycsin - were you able to solve the issue?

[ycsin]

@cfriedt
@nordic-krch pointed out something that gave me some idea to pin point the issue: adding a delay between printk and LOG to see if they are competing for the uart, but I cant find time to test that yet.

I'm not sure if stm32's uart driver support poll_out and interrupt APIs at the same time, but most likely it is not supported, maybe @erwango @ABOSTM @FRASTM can comment on this one?

So this is still an open issue, and to be exact I'm not sure what's the cause, maybe just not supported by uart_stm32 driver

[erwango]

I'm not sure if stm32's uart driver support poll_out and interrupt APIs at the same time, but most likely it is not supported

It is.

[emillindq]

I am 99% sure this problem has to do with mixed polling/irq calls. I just pulled latest Zephyr and no logs came out if LOG, SHELL & PM was active. Shell uart backend calls the irq based uart functions, and receives its callbacks fine in the beginning but then as soon as the banner comes ("Booting Zephyr OS...") it stops to receive callbacks. The banner uses polling based uart calls. Disable the banner and it works flawless.

I also tracked it down to commit e3f4907 before this commit it worked

[erwango]

@emillindq, @ycsin Can you check if #39752 is fixing this issue ?

[emillindq]

@emillindq, @ycsin Can you check if #39752 is fixing this issue ?

Unfortunately not, although for one of my builds it does. I suspect it has to do with order of execution and this PR resolves one case of multiple. Once again, disabling CONFIG_BOOT_BANNER with mentioned PR and LOG_XXX messages comes out

[erwango]

@emillindq, @ycsin New attempt from @jdascenzio: #40173

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.