Project

General

Profile

Actions

Emulator Issues #12470

open

Performing initial console setup on System Menu 2.0 through 3.0 hangs on a black screen after setting everything up

Added by pokechu22 almost 3 years ago. Updated over 2 years ago.

Status:
Accepted
Priority:
Normal
Assignee:
-
% Done:

0%

Operating system:
N/A
Issue type:
Bug
Milestone:
Regression:
No
Relates to usability:
No
Relates to performance:
No
Easy:
No
Relates to maintainability:
No
Regression start:
Fixed in:

Description

Game Name?

System Menu

What's the problem? Describe what went wrong.

When performing initial setup on old system menu versions, the menu hangs on a black screen after finishing the setup instead of rebooting into the menu. Stopping and then starting emulation loads the menu as intended. This does not apply to versions after 3.1U.

What steps will reproduce the problem?

I own Super Paper Mario (USA revision 0), which comes with System Menu 2.0 on the disc. It probably is possible to use just NUSDownloader to set everything up, but I don't have exact steps.

  1. Rename the Dolphin Emulator folder to something else to avoid damaging existing NAND data (and to start from a new, clean NAND)
  2. Right-click Super Paper Mario in the games list and select "Perform System Update"
  3. After the update finishes, select Tools → Load Wii System Menu 2.0U.
  4. Select a country, then press OK, then press OK on the screen mentioning the screen dimming feature.
  5. Disconnect your computer from the internet, and then select OK to proceed to the system update. The update should fail. (I have also tried doing it with the internet connected, and the update usually fails with Error 32004 (apparently related to unofficial software). Either way, it's System Menu 2.0 that matters, so don't update).
  6. Select OK on the error screen, and then select Wii Menu.
  7. The system will hang on a black screen.
  8. The console will properly shutdown if escape is pressed (this has happened every time I tested recently, but I'm not 100% sure it's always the case; I remember needing to press escape twice in one case. Note also that escape does not shut down during the configuration process, so maybe that's what happened.)

I tested System Menu 2.2U by installing System Menu 2.0U from Super Paper Mario, and then applying the System Menu 2.2U WAD from NUSDownloader (RVL-WiiSystemmenu-193.wad). I tested System Menu 3.0U by installing System Menu 3.1U from Wii Fit and then applying the System Menu 3.0U WAD (RVL-WiiSystemmenu-225.wad). Neither of those setups is exactly accurate with regards to installed IOSs, but it seemed to boot at least.

Is the issue present in the latest development version?

Tested 5.0-13698.

Is the issue present in the latest stable version?

Not tested, but I'm pretty sure that some of the needed features to test this don't exist in 5.0.

What are your PC specifications?

  • CPU: AMD A6-340M APU with Radeon(tm) Graphics, 1500 Mhz, 4 Core(s), 4 Logical Processor(s)
  • GPU: AMD Radeon HD 6520G
  • OS: Windows 10 Pro (Insider preview) 10.0.19043.906

Is there anything else that can help developers narrow down the issue?

I specifically tested System Menu 2.0U, 2.2U, and 3.0U (along with 3.1U and a few other versions). There is no 2.1U, so I didn't test that.

The end of the logs for 2.0U and 2.2U look like this:

02:28:609 Core\IOS\FS\FileSystemProxy.cpp:111 E[IOS_FS]: Command: ReadDirectory(/shared2/sys/SYSCONF): Result -101
02:28:610 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: GetMetadata(/shared2/sys/SYSCONF): Result 0
02:28:610 Core\IOS\IOS.cpp:529 I[IOS]: Opening /shared2/sys/SYSCONF (mode 2, fd 9)
02:28:610 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/shared2/sys/SYSCONF): Result 0
02:28:611 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/shared2/sys/SYSCONF, 0x0111cb40, 16384): Result 0
02:28:633 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/shared2/sys/SYSCONF): Result 0
02:28:634 Core\IOS\IOS.cpp:617 W[IOS]: Previous request to device /dev/fs blocked emulation for 16557 microseconds.
02:28:706 Core\IOS\USB\Bluetooth\BTEmu.cpp:1360 I[IOS_WIIMOTE]: Command: HCI_CMD_RESET
02:29:126 Core\IOS\IOS.cpp:529 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 1, fd 7)
02:29:127 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
02:29:127 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Read(/title/00000001/00000002/data/state.dat, 0x010fd740, 32): Result 0
02:29:127 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
02:29:129 Core\IOS\IOS.cpp:529 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 2, fd 7)
02:29:129 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
02:29:129 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/title/00000001/00000002/data/state.dat, 0x010fd740, 32): Result 0
02:29:145 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
02:29:145 Core\IOS\IOS.cpp:617 W[IOS]: Previous request to device /dev/fs blocked emulation for 14748 microseconds.
02:29:203 Core\HW\DSPHLE\UCodes\UCodes.cpp:228 I[DSPHLE]: Switching to ROM ucode
02:29:203 Core\HW\DSPHLE\UCodes\ROM.cpp:28 I[DSPHLE]: UCode_Rom - initialized
02:29:204 Core\IOS\Network\KD\NetKDRequest.cpp:153 I[IOS_WC24]: NET_KD_REQ: IOCTL_NWC24_REQUEST_SHUTDOWN
02:29:206 Core\HW\SI\SI_DeviceGCController.cpp:94 I[SI]: PAD - Recalibrate
02:29:206 Core\HW\SI\SI_DeviceGCController.cpp:322 I[SI]: PAD 0 set to mode 3
02:29:216 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000001)
02:29:217 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000000)
02:29:890 Core\IOS\STM\STM.cpp:42 I[IOS_STM]: /dev/stm/immediate - IOCtl:
02:29:890 Core\IOS\STM\STM.cpp:43 I[IOS_STM]:     IOCTL_STM_HOTRESET

The log for 3.0U looks like this:

33:06:203 Core\IOS\FS\FileSystemProxy.cpp:111 E[IOS_FS]: Command: ReadDirectory(/shared2/sys/SYSCONF): Result -101
33:06:203 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: GetMetadata(/shared2/sys/SYSCONF): Result 0
33:06:203 Core\IOS\IOS.cpp:529 I[IOS]: Opening /shared2/sys/SYSCONF (mode 2, fd 11)
33:06:204 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/shared2/sys/SYSCONF): Result 0
33:06:204 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/shared2/sys/SYSCONF, 0x0113cb20, 16384): Result 0
33:06:229 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/shared2/sys/SYSCONF): Result 0
33:06:229 Core\IOS\IOS.cpp:617 W[IOS]: Previous request to device /dev/fs blocked emulation for 19663 microseconds.
33:06:289 Core\IOS\USB\Bluetooth\BTEmu.cpp:1360 I[IOS_WIIMOTE]: Command: HCI_CMD_RESET
33:06:716 Core\IOS\IOS.cpp:529 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 1, fd 7)
33:06:717 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
33:06:717 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Read(/title/00000001/00000002/data/state.dat, 0x0111c720, 32): Result 0
33:06:718 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
33:06:718 Core\IOS\IOS.cpp:529 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 2, fd 7)
33:06:719 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
33:06:719 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/title/00000001/00000002/data/state.dat, 0x0111c720, 32): Result 0
33:06:735 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
33:06:735 Core\IOS\IOS.cpp:617 W[IOS]: Previous request to device /dev/fs blocked emulation for 15443 microseconds.
33:06:773 Core\HW\DSPHLE\UCodes\UCodes.cpp:228 I[DSPHLE]: Switching to ROM ucode
33:06:773 Core\HW\DSPHLE\UCodes\ROM.cpp:28 I[DSPHLE]: UCode_Rom - initialized
33:06:774 Core\IOS\Network\KD\NetKDRequest.cpp:153 I[IOS_WC24]: NET_KD_REQ: IOCTL_NWC24_REQUEST_SHUTDOWN
33:06:777 Core\HW\SI\SI_DeviceGCController.cpp:94 I[SI]: PAD - Recalibrate
33:06:777 Core\HW\SI\SI_DeviceGCController.cpp:322 I[SI]: PAD 0 set to mode 3
33:06:792 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000001)
33:06:792 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000000)

(note that IOCTL_STM_HOTRESET is missing in 3.0U).

IOCTL_STM_HOTRESET is currently implemented only as logging, so it hanging for that makes sense. 3.0U hanging makes less sense (and may be caused by a separate issue).

Actions #1

Updated by pokechu22 almost 3 years ago

Super Mario Galaxy 1 comes with System Menu 3.0U, and I can reproduce the issue using that as well (which is probably easier than installing 3.1U and then replacing the System Menu).

Actions #2

Updated by leoetlino almost 3 years ago

  • Status changed from New to Accepted
Actions #3

Updated by JMC4789 over 2 years ago

Can you try with LLE audio? Older versions of the System Menu come with a DSP microcode Dolphin doesn't emulate well.

Actions #4

Updated by pokechu22 over 2 years ago

It doesn't seem to be that.

2.0U LLE (Super paper Mario):

25:21:864 Core\IOS\FS\FileSystemProxy.cpp:111 E[IOS_FS]: Command: ReadDirectory(/shared2/sys/SYSCONF): Result -101
25:21:864 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: GetMetadata(/shared2/sys/SYSCONF): Result 0
25:21:864 Core\IOS\IOS.cpp:594 I[IOS]: Opening /shared2/sys/SYSCONF (mode 2, fd 9)
25:21:864 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/shared2/sys/SYSCONF): Result 0
25:21:864 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/shared2/sys/SYSCONF, 0x0111cb40, 16384): Result 0
25:21:869 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/shared2/sys/SYSCONF): Result 0
25:22:381 Core\IOS\IOS.cpp:594 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 1, fd 7)
25:22:381 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
25:22:381 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Read(/title/00000001/00000002/data/state.dat, 0x010fd740, 32): Result 0
25:22:382 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
25:22:382 Core\IOS\IOS.cpp:594 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 2, fd 7)
25:22:383 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
25:22:383 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/title/00000001/00000002/data/state.dat, 0x010fd740, 32): Result 0
25:22:386 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
25:22:460 Core\DSP\Interpreter\DSPInterpreter.cpp:205 I[DSPLLE]: DSP_CONTROL RESET
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 4f (sigNum:3)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 59 (sigNum:3)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at f4c (sigNum:3)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at f52 (sigNum:4)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 2e (sigNum:5)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 45 (sigNum:5)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 653 (sigNum:5)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at e99 (sigNum:5)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at ea6 (sigNum:5)
25:22:460 Core\DSP\DSPAnalyzer.cpp:88 I[DSPLLE]: Finished analysis.
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 807e (sigNum:1)
25:22:460 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 8078 (sigNum:3)
25:22:460 Core\DSP\DSPAnalyzer.cpp:88 I[DSPLLE]: Finished analysis.
25:22:463 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000001)
25:22:463 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000000)
25:22:569 Core\IOS\STM\STM.cpp:42 I[IOS_STM]: /dev/stm/immediate - IOCtl:
25:22:569 Core\IOS\STM\STM.cpp:43 I[IOS_STM]:     IOCTL_STM_HOTRESET

3.0U LLE (Super Mario Galaxy):

28:38:576 Core\IOS\FS\FileSystemProxy.cpp:111 E[IOS_FS]: Command: ReadDirectory(/shared2/sys/SYSCONF): Result -101
28:38:576 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: GetMetadata(/shared2/sys/SYSCONF): Result 0
28:38:576 Core\IOS\IOS.cpp:594 I[IOS]: Opening /shared2/sys/SYSCONF (mode 2, fd 11)
28:38:576 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/shared2/sys/SYSCONF): Result 0
28:38:576 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/shared2/sys/SYSCONF, 0x0113cb20, 16384): Result 0
28:38:580 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/shared2/sys/SYSCONF): Result 0
28:39:076 Core\IOS\IOS.cpp:594 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 1, fd 7)
28:39:076 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
28:39:076 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Read(/title/00000001/00000002/data/state.dat, 0x0111c720, 32): Result 0
28:39:078 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
28:39:079 Core\IOS\IOS.cpp:594 I[IOS]: Opening /title/00000001/00000002/data/state.dat (mode 2, fd 7)
28:39:079 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: OpenFile(/title/00000001/00000002/data/state.dat): Result 0
28:39:079 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Write(/title/00000001/00000002/data/state.dat, 0x0111c720, 32): Result 0
28:39:081 Core\IOS\FS\FileSystemProxy.cpp:111 I[IOS_FS]: Command: Close(/title/00000001/00000002/data/state.dat): Result 0
28:39:137 Core\DSP\Interpreter\DSPInterpreter.cpp:205 I[DSPLLE]: DSP_CONTROL RESET
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 51 (sigNum:3)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 5b (sigNum:3)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at fea (sigNum:3)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at ff0 (sigNum:4)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 30 (sigNum:5)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 47 (sigNum:5)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 66b (sigNum:5)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at f35 (sigNum:5)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at f42 (sigNum:5)
28:39:138 Core\DSP\DSPAnalyzer.cpp:88 I[DSPLLE]: Finished analysis.
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 807e (sigNum:1)
28:39:138 Core\DSP\DSPAnalyzer.cpp:164 I[DSPLLE]: Idle skip location found at 8078 (sigNum:3)
28:39:138 Core\DSP\DSPAnalyzer.cpp:88 I[DSPLLE]: Finished analysis.
28:39:143 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000001)
28:39:143 Core\HW\ProcessorInterface.cpp:115 W[PI]: Fifo reset (00000000)

Also note that with HLE, the following is logged for 2.0U right before it resets:

20:50:565 Core\HW\DSPHLE\UCodes\UCodes.cpp:228 I[DSPHLE]: Switching to ROM ucode
20:50:565 Core\HW\DSPHLE\UCodes\ROM.cpp:28 I[DSPHLE]: UCode_Rom - initialized

And with DumpUCode = True, the file that is dumped (at least during the setup process) is DSP_UC_ADBC06BD which seems to be a known version of the AX UCode.

Actions

Also available in: Atom PDF