BIOS升级失败

Hardware SIG
1

相关日志：

2025-12-20 06:37:52.863499 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:37:53.855937 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:37:54.557612 unknown_service ERROR: video.lua(538): record_video: frame_process data over iframeno = 20, file_len = 258172
2025-12-20 06:37:54.668295 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:54.769523 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:54.861021 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:54.963216 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:55.066428 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:55.168650 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:55.261653 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:55.356151 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:37:55.365639 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:55.467310 unknown_service ERROR: km_api.lua(174): Get keyboard state fail, usb_id=0, fn_id=0, ret=22
2025-12-20 06:37:56.315609 firmware_mgmt NOTICE: active_condition_handle.lua(92): wait_active_apply_status fw_type = BIOS status = Apply, timeout = 300S, wait_time = 5S
2025-12-20 06:37:56.316054 firmware_mgmt NOTICE: active_condition_handle.lua(105): wait_active_result start wait fw_type = BIOS target status = Ready
2025-12-20 06:37:56.358093 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:37:56.650660 unknown_service NOTICE: screen.lua(165): set screen poweroff state to false
2025-12-20 06:37:57.857689 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:37:58.284982 fructrl NOTICE: pwr_restore.lua(161): [System:1]Power restore policy.........................................always-on.
2025-12-20 06:37:58.285905 fructrl NOTICE: pwr_restore.lua(36): [System:1]Start delay time.
2025-12-20 06:37:58.843975 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:37:59.016460 fructrl NOTICE: pwr_restore.lua(47): [System:1]End delay time. (delay=68)
2025-12-20 06:37:59.083386 fructrl NOTICE: pwr_restore.lua(137): [System:1]wait PwrOnLocked unlock
2025-12-20 06:38:00.152369 unknown_service NOTICE: screen.lua(87): begin to screenshot last frame
2025-12-20 06:38:00.350711 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:38:00.425353 unknown_service NOTICE: screen.lua(95): finish to screenshot last frame
2025-12-20 06:38:01.337031 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:38:02.839614 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:38:03.836737 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:38:05.331564 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:38:06.328168 unknown_service ERROR: ipmb.lua(119): ipmb push msg failed, err: ipmb bus [0] is busy.
2025-12-20 06:38:06.614705 bios ERROR: spi_flash.lua(301): [spi]check_device_ready: ready fail
2025-12-20 06:38:06.616724 bios ERROR: upgrade_executor.lua(212): [bios]spi_driver (executor): before fail

dmesg：

[18107.216693] usb device-0: gadget disconnect
[18107.216717] usb device-0: reset configuration. gadget state <7>
[18107.216732] usb device-0: Keyboard disabled
[18107.216743] usb device-0: Mouse disabled
[18107.225582] 159,2025-12-22 02:40:02,42320,hisfc_drv_probe,834,probe bus 0
[18107.232680] 160,2025-12-22 02:40:02,42320,hisfc_drv_request_permission,628,sfc0 use hwid 4
[18107.242547] 161,2025-12-22 02:40:02,42320,hisfc_flash_scan_init,1050,hisfc_probe start bus 0
[18107.251676] 162,2025-12-22 02:40:02,42320,sfc_sys_set_controller_clk,246,bus 0 clock frequency of is all set!
[18107.262281] 163,2025-12-22 02:40:02,42320,sfc_sys_clock_operator,213,CLOSE 1711 SFC Clock Success!
[18107.271528] 164,2025-12-22 02:40:02,42320,sfc_sys_clock_operator,223,Open 1711 SFC Clock Success!
[18107.280953] 165,2025-12-22 02:40:02,42320,sfc_core_spi_probe,2053,Spi(cs0) ID: 0x00000000 0x00000000
[18107.290455] 166,2025-12-22 02:40:02,42320,sfc_core_spi_probe,2056,Spi(cs0): RDID not right!
[18107.299234] 167,2025-12-22 02:40:02,42320,sfc_core_spi_probe,2053,Spi(cs1) ID: 0x00000000 0x00000000
[18107.308674] 168,2025-12-22 02:40:02,42320,sfc_core_spi_probe,2056,Spi(cs1): RDID not right!
[18107.319629] 169,2025-12-22 02:40:02,42320,hisfc_flash_scan_init,1065,hisfc_base_probe failed. bus 0
[18107.328966] 170,2025-12-22 02:40:02,42320,hisfc_std_init,1096,hisfc_flash_scan_init bus 0 failed -14
[18107.338249] 171,2025-12-22 02:40:02,42320,hisfc_drv_probe,850,hisfc_std_init failed -14
[18107.346538] hi_sfc0: probe of 8640000.sfc0 failed with error -14
[18107.444852] 172,2025-12-22 02:40:02,2600,mctp_reset,1477,reset mctp ok!
[18107.452646] 173,2025-12-22 02:40:02,2600,mctp_dereset,1501,dereset mctp ok!

和ipmb bus [0] is busy的异常有关吗，应该如何排查？

调用mtd_api.write接口卡死
BIOS升级问题
新加组件调用spi_flash 相关接口失败
升级EXU的CPLD后无法加载Riser CSR
2

可以看下能否手动加载驱动成功，加载失败的话可能就是硬件问题。

3

手动切SPI后加载驱动是OK的

~ /home/Administrator # insmod /lib/modules/ko/sfc0_drv.ko
~ /home/Administrator # dmesg
[141607.533250] 156,2025-12-24 03:36:29,48014,hisfc_drv_probe,834,probe bus 0
[141607.540253] 157,2025-12-24 03:36:29,48014,hisfc_drv_request_permission,628,sfc0 use hwid 4
[141607.549432] 158,2025-12-24 03:36:29,48014,hisfc_flash_scan_init,1050,hisfc_probe start bus 0
[141607.558202] 159,2025-12-24 03:36:29,48014,sfc_sys_set_controller_clk,246,bus 0 clock frequency of is all set!
[141607.571169] 160,2025-12-24 03:36:29,48014,sfc_sys_clock_operator,213,CLOSE 1711 SFC Clock Success!
[141607.580957] 161,2025-12-24 03:36:29,48014,sfc_sys_clock_operator,223,Open 1711 SFC Clock Success!
[141607.590578] 162,2025-12-24 03:36:29,48014,sfc_core_spi_probe,2053,Spi(cs0) ID: 0x00000000 0x00000000
[141607.601152] 163,2025-12-24 03:36:29,48014,sfc_core_spi_probe,2056,Spi(cs0): RDID not right!
[141607.611573] 164,2025-12-24 03:36:29,48014,sfc_core_spi_probe,2053,Spi(cs1) ID: 0xc22539c2 0x2539c225
[141607.622923] 165,2025-12-24 03:36:29,48014,sfc_spi_search_rw,125,dump[3] isread(1) iftype:1
[141607.631955] 166,2025-12-24 03:36:29,48014,sfc_spi_search_rw,125,dump[1] isread(0) iftype:1
[141607.642494] 167,2025-12-24 03:36:29,48014,sfc_core_show_spi,1690,Spi(cs 1):
[141607.649999] 168,2025-12-24 03:36:29,48014,sfc_core_show_spi,1691,Name:"MX25U25645G"
[141607.688387] Creating 1 MTD partitions on "hi_sfc0.1":
[141607.693752] 0x000000000000-0x000002000000 : "sfc0cs1"
~ /home/Administrator # ls -l /dev/mtd
mtd0       mtd0ro     mtdblock0
~ /home/Administrator # ls -l /dev/mtd0
crw-rw----    1 root     root       90,   0 Dec 24 03:36 /dev/mtd0
~ /home/Administrator #
4

日志报错在spi_flash.check_device_ready，现象似乎是spi_flash.set_spi_owner没有成功，set_spi_owner失败会有记录吗？

image
image890×261 15.2 KB

5

有维护日志记录spi通道切换

6

维护日志有切换记录，看不出来是否切换失败
2025-12-20 06:37:51 INFO : SVR-0000000,Switch spi to BMC
2025-12-20 06:38:06 INFO : SVR-0000000,Switch spi to BIOS
2025-12-20 06:39:33 WARN : SVR-0000000,Server power failure occurred at 2025-12-20 06:36:31 UTC, The power has been already restored.
2025-12-20 06:39:48 INFO : SVR-0000000,Set watchdog timer to (RAW:02-01-00-00-28-23) successfully
2025-12-20 06:41:59 INFO : SVR-0000000,Set watchdog timer to (RAW:03-00-00-00-b8-0b) successfully

7

这个是成功日志，这个升级失败是必现的吗

8

必现的，使用手动切换、加载驱动的方式是成功的，不知道和代码流程有什么差异

bf50f6b14f64f5ca07f8651f6a848476
bf50f6b14f64f5ca07f8651f6a848476302×442 5.14 KB

~ /home/Administrator # insmod /lib/modules/ko/sfc0_drv.ko
~ /home/Administrator # dmesg
[141607.533250] 156,2025-12-24 03:36:29,48014,hisfc_drv_probe,834,probe bus 0
[141607.540253] 157,2025-12-24 03:36:29,48014,hisfc_drv_request_permission,628,sfc0 use hwid 4
[141607.549432] 158,2025-12-24 03:36:29,48014,hisfc_flash_scan_init,1050,hisfc_probe start bus 0
[141607.558202] 159,2025-12-24 03:36:29,48014,sfc_sys_set_controller_clk,246,bus 0 clock frequency of is all set!
[141607.571169] 160,2025-12-24 03:36:29,48014,sfc_sys_clock_operator,213,CLOSE 1711 SFC Clock Success!
[141607.580957] 161,2025-12-24 03:36:29,48014,sfc_sys_clock_operator,223,Open 1711 SFC Clock Success!
[141607.590578] 162,2025-12-24 03:36:29,48014,sfc_core_spi_probe,2053,Spi(cs0) ID: 0x00000000 0x00000000
[141607.601152] 163,2025-12-24 03:36:29,48014,sfc_core_spi_probe,2056,Spi(cs0): RDID not right!
[141607.611573] 164,2025-12-24 03:36:29,48014,sfc_core_spi_probe,2053,Spi(cs1) ID: 0xc22539c2 0x2539c225
[141607.622923] 165,2025-12-24 03:36:29,48014,sfc_spi_search_rw,125,dump[3] isread(1) iftype:1
[141607.631955] 166,2025-12-24 03:36:29,48014,sfc_spi_search_rw,125,dump[1] isread(0) iftype:1
[141607.642494] 167,2025-12-24 03:36:29,48014,sfc_core_show_spi,1690,Spi(cs 1):
[141607.649999] 168,2025-12-24 03:36:29,48014,sfc_core_show_spi,1691,Name:"MX25U25645G"
[141607.688387] Creating 1 MTD partitions on "hi_sfc0.1":
[141607.693752] 0x000000000000-0x000002000000 : "sfc0cs1"
~ /home/Administrator #
9

可以看下是不是升级时mtd0的权限问题，正常升级权限应该是crw-rw---- 1 secbox secbox 90, 0 Dec 26 10:16 /dev/mtd0

10

失败的情况下sfc驱动报错了，这时是不是不会有/dev/mtd0目录？

11

是的

12

还是得先解决驱动报错的问题

13

有驱动报错的具体内容吗

14

就是dmesg看到的错误

15

可能没有sfc0cs0，明确打印全F或全0的sfc片选外面是否有接flash颗粒，若没有接颗粒，则请硬件焊接颗粒

16

手动切换的时候看到是cs1成功了，cs0是必须的吗

17

应该是的

18

在相同机型的老硬件上测试可以正常升级，也是只有cs1。
失败的是该机型的新硬件，做了部分硬件改动。
Name是什么决定的，是flash型号决定的吗，会不会是flash差异导致的？

image
image790×589 58.3 KB

19

驱动会对spi flash做适配，适配的时候会根据厂家型号命名。