Zephyr: Sample ipsp: bluetooth: not functional on disco_l475_iot1

[cpriouzeau]

Since the integration of "__ZEPHYR_SUPERVISOR__ macro" on cmake file,
the bluetooth ipsp sample are not functionnal, Zephyr remains blocked in the init of bluetooth.

With the proposition made on pull request #7567, the sample ipsp work again.

Info:
Pull request used to revert patch: #7567
detected on Master branch: c4a62e0427cc7ecd78c18945957a8eb46b46aa73

[AdithyaBaglody]

Drivers of Bluetooth haven't been touched for adding Zephyr_supervisor macro.
Can you please provide more info on where exactly it is getting stuck and the board that is being used.
What I can see is that qemu is working just fine (which are the whitelisted platforms in samples.yaml)

[cpriouzeau]

@AdithyaBaglody
My setup:
board: disco_l475_iot1
zephyr: master branch (include TAG v1.12.0-rc1)
sample: bluetooth/ipsp
The issue are visible only on board at runtime not during the compilation time.
At runtime I have seen that the bluetooth hci spi driver are never registered while it's compiled

compilation:
cd zephyr
source zephyr-env.sh
cd samples/bluetooth/ipsp
mkdir build/disco_l475_iot1
cd build/disco_l475_iot1
cmake -GNinja -DBOARD=disco_l475_iot1 ../..; ninja

Trace on serial console, with the issue:
Booting Zephyr OS v1.12.0-rc1-41-gfcc56e3
Trace on serial console, with patch from #7567
� Booting Zephyr OS v1.12.0-rc1-44-ge438f3d
[bt] [WRN] set_flow_control: Controller to host flow control not supported
[bt] [WRN] hci_vs_init: Vendor HCI extensions not available
[bt] [WRN] setup_id_addr: Read Static Addresses command not available
[bt] [WRN] setup_id_addr: Using temporary static random address e6:85:68:1e:11:cd
[bt] [INF] bt_dev_show_info: Identity: e6:85:68:1e:11:cd (random)
[bt] [INF] bt_dev_show_info: HCI: version 4.1 (0x07) revision 0x3107, manufacturer 0x0030
[bt] [INF] bt_dev_show_info: LMP: version 4.1 (0x07) subver 0x0023
[bt] [WRN] bt_pub_key_gen: ECC HCI commands not available
[ipsp] [INF] init_app: Run IPSP sample
[ipsp] [INF] listen: Starting to wait

[cpriouzeau]

@AdithyaBaglody tested with patch of #7784 but the issue is still present at runtime.

[AdithyaBaglody]

@cpriouzeau I tried this on Arduino 101 and quark c1000. It seems to work fine on these boards. I actually do not have the discovery board with me to test this out.

At runtime I have seen that the bluetooth hci spi driver are never registered while it's compiled

But the cmake changes shouldn't have any effect on this. Also the spi seems to be compiled correctly.
Can you please do git bisect and let me know the faulting commit.

[SebastianBoe]

This does not affect BOARD=nrf52840_pca10056 either. I don't have a disco board to reproduce the isssue.

[SebastianBoe]

Diffing the build directory of disco_l475_iot1 before and after the offending PR was merged shows that the PR changed the FW in many ways, any one of them could be the root cause.

for instance.

diff b_before_merge/zephyr/include/generated/generated_dts_board.conf b_after_merge/zephyr/include/generated/generated_dts_board.conf
216,219c216,219
< ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_FUNCTION_0=[2, 39]
< ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_FUNCTION_1=[3, 39]
< ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_PIN_0=tx
< ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_PIN_1=rx
---
> ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_FUNCTION_0=[3, 39]
> ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_FUNCTION_1=[2, 39]
> ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_PIN_0=rx
> ST_STM32_USART_40004400_PINMUX_USART2_0_RX_TX_PIN_1=tx
232,235c232,235
< ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_FUNCTION_0=[22, 39]
< ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_FUNCTION_1=[23, 39]
< ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_PIN_0=tx
< ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_PIN_1=rx
---
> ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_FUNCTION_0=[23, 39]
> ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_FUNCTION_1=[22, 39]
> ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_PIN_0=rx
> ST_STM32_USART_40013800_PINMUX_USART1_0_RX_TX_PIN_1=tx

[erwango]

@SebastianBoe : Above change should not have any effect since device tree generated pinmux bits are not used. But it's interesting to see #7567 could have impacted this.
Can you put a link to the full generated_dts_board files?

[SebastianBoe]

I'd rather post steps to reproduce.

cd samples/bluetooth/ipsp

git checkout c674167fea
cleanbuild
mv b b_before_pr_6835

git checkout c07ec386bf
cleanbuild
mv b b_after_pr_6835

kdiff b_before_pr_6835 b_after_pr_6835

In the diff one can see several changes, (but not the one I reported earlier for some unknown reason), e.g. that several driver libraries are now enabled and that the code size has increased by 8 bytes.

EDIT: New driver libraries being enabled are most likely not a root cause, the PR re-organized existing source files into new libraries, so it is not unexpected and possibly inconsequential.

[erwango]

From what I see there is no change in generated_dts_board.h/conf nor in .config files.
So drivers selection and configuration is not changed
Only changes I can see are build/link related (addresses, libraries, ..)

[SebastianBoe]

Yeah ... It appears to be too difficult to debug this through static analysis.

Someone with the affected HW is going to have to debug.

EDIT: Or bisect, as someone has already proposed.

[Vudentz]

Btw, shall we remove the Bluetooth tag? It doesn't seem Bluetooth subsys is the culprit here.

[erwango]

Git bisect provides the following culprit: b0db28b512c8306c88f3240dc8da1a1f4e79377a

[AdithyaBaglody]

@erwango did you try it on the discovery board?

[SebastianBoe]

The order in which devices are initialized changed. If the device init priorities
were not set correctly, one could have been lucky with the device
init ordering until now.

I can't test this theory without the HW though.

devconfig       0x0000000008016c30      0x150
                0x0000000008016c30                __devconfig_start = .
 *(.devconfig.*)
 .devconfig.init
                0x0000000008016c30        0xc zephyr/libzephyr.a(soc.c.obj)
 .devconfig.init
                0x0000000008016c3c        0xc zephyr/libzephyr.a(uart_console.c.obj)
 .devconfig.init
                0x0000000008016c48        0xc zephyr/libzephyr.a(exti_stm32.c.obj)
 .devconfig.init
                0x0000000008016c54        0xc zephyr/libzephyr.a(stm32_ll_clock.c.obj)
 .devconfig.init
                0x0000000008016c60       0x60 zephyr/libzephyr.a(gpio_stm32.c.obj)
 .devconfig.init
                0x0000000008016cc0       0x18 zephyr/libzephyr.a(i2c_ll_stm32.c.obj)
 .devconfig.init
                0x0000000008016cd8        0xc zephyr/libzephyr.a(pwm_stm32.c.obj)
 .devconfig.init
                0x0000000008016ce4        0xc zephyr/libzephyr.a(uart_stm32.c.obj)
 .devconfig.init
                0x0000000008016cf0        0xc zephyr/libzephyr.a(spi_ll_stm32.c.obj)
 .devconfig.init
                0x0000000008016cfc        0xc zephyr/libzephyr.a(spi.c.obj)
 .devconfig.init
                0x0000000008016d08        0xc zephyr/libzephyr.a(entropy_stm32.c.obj)
 .devconfig.init
                0x0000000008016d14        0xc zephyr/libzephyr.a(sys_clock_init.c.obj)
 .devconfig.init
                0x0000000008016d20        0xc zephyr/arch/arm/core/cortex_m/mpu/libarch__arm__core__cortex_m__mpu.a(arm_mpu.c.obj)
 .devconfig.init
                0x0000000008016d2c        0xc zephyr/boards/boards/arm/disco_l475_iot1/libboards__arm__disco_l475_iot1.a(pinmux.c.obj)
 .devconfig.init
                0x0000000008016d38        0xc zephyr/subsys/net/ip/libsubsys__net__ip.a(net_core.c.obj)
 .devconfig.init
                0x0000000008016d44        0xc zephyr/subsys/net/ip/l2/libsubsys__net__ip__l2.a(bluetooth.c.obj)
 .devconfig.init
                0x0000000008016d50        0xc zephyr/subsys/net/lib/app/libsubsys__net__lib__app.a(init.c.obj)
 .devconfig.init
                0x0000000008016d5c        0xc zephyr/kernel/libkernel.a(mem_slab.c.obj)
 .devconfig.init
                0x0000000008016d68        0xc zephyr/kernel/libkernel.a(mempool.c.obj)
 .devconfig.init
                0x0000000008016d74        0xc zephyr/kernel/libkernel.a(system_work_q.c.obj)
 *(SORT(.devconfig*))
                0x0000000008016d80                __devconfig_end = .

devconfig       0x0000000008016c30      0x150
                0x0000000008016c30                __devconfig_start = .
 *(.devconfig.*)
 .devconfig.init
                0x0000000008016c30        0xc zephyr/libzephyr.a(soc.c.obj)
 .devconfig.init
                0x0000000008016c3c        0xc zephyr/libzephyr.a(uart_console.c.obj)
 .devconfig.init
                0x0000000008016c48        0xc zephyr/libzephyr.a(exti_stm32.c.obj)
 .devconfig.init
                0x0000000008016c54        0xc zephyr/libzephyr.a(stm32_ll_clock.c.obj)
 .devconfig.init
                0x0000000008016c60        0xc zephyr/libzephyr.a(spi.c.obj)
 .devconfig.init
                0x0000000008016c6c        0xc zephyr/libzephyr.a(sys_clock_init.c.obj)
 .devconfig.init
                0x0000000008016c78        0xc zephyr/arch/arm/core/cortex_m/mpu/libarch__arm__core__cortex_m__mpu.a(arm_mpu.c.obj)
 .devconfig.init
                0x0000000008016c84        0xc zephyr/boards/boards/arm/disco_l475_iot1/libboards__arm__disco_l475_iot1.a(pinmux.c.obj)
 .devconfig.init
                0x0000000008016c90        0xc zephyr/subsys/net/ip/libsubsys__net__ip.a(net_core.c.obj)
 .devconfig.init
                0x0000000008016c9c        0xc zephyr/subsys/net/ip/l2/libsubsys__net__ip__l2.a(bluetooth.c.obj)
 .devconfig.init
                0x0000000008016ca8        0xc zephyr/subsys/net/lib/app/libsubsys__net__lib__app.a(init.c.obj)
 .devconfig.init
                0x0000000008016cb4       0x60 zephyr/drivers/gpio/libdrivers__gpio.a(gpio_stm32.c.obj)
 .devconfig.init
                0x0000000008016d14       0x18 zephyr/drivers/i2c/libdrivers__i2c.a(i2c_ll_stm32.c.obj)
 .devconfig.init
                0x0000000008016d2c        0xc zephyr/drivers/pwm/libdrivers__pwm.a(pwm_stm32.c.obj)
 .devconfig.init
                0x0000000008016d38        0xc zephyr/drivers/serial/libdrivers__serial.a(uart_stm32.c.obj)
 .devconfig.init
                0x0000000008016d44        0xc zephyr/drivers/spi/libdrivers__spi.a(spi_ll_stm32.c.obj)
 .devconfig.init
                0x0000000008016d50        0xc zephyr/drivers/entropy/libdrivers__entropy.a(entropy_stm32.c.obj)
 .devconfig.init
                0x0000000008016d5c        0xc zephyr/kernel/libkernel.a(mem_slab.c.obj)
 .devconfig.init
                0x0000000008016d68        0xc zephyr/kernel/libkernel.a(mempool.c.obj)
 .devconfig.init
                0x0000000008016d74        0xc zephyr/kernel/libkernel.a(system_work_q.c.obj)
 *(SORT(.devconfig*))
                0x0000000008016d80                __devconfig_end = .

[erwango]

Among files modified in b0db28b, issue is in drivers/gpio/CMakeLists.txt

[erwango]

@AdithyaBaglody , yes tested on disco board.
With issue narrowed down to drivers/gpio/CMakeLists.tx, i think issue should be easier to analyse

[erwango]

@SebastianBoe: \o/
I changed GPIO priority from CONFIG_KERNEL_INIT_PRIORITY_DEVICE to CONFIG_KERNEL_INIT_PRIORITY_DEFAULT, and it is working now!

Thanks!

[AdithyaBaglody]

@SebastianBoe Amazing catch. the drivers init was rearranged since all the drivers had same priority ".init_POST_KERNEL50"