search

FEX-Emu / FEX

A fast usermode x86 and x86-64 emulator for Arm64 Linux
https://fex-emu.com
MIT License
1.99k stars 103 forks source link

Unvanquished: Crashes with error about DEP #2175

Open icecream95 opened 1 year ago

icecream95 commented 1 year ago

What Game

Unvanquished, downloaded from https://unvanquished.net/download/

Describe the bug

Trying to launch Unvanquished fails because the nacl_loader process crashes.

To Reproduce

  1. Download the launcher for Linux
  2. Unzip and execute the launcher, install Unvanquished
  3. Hit the button to start the game
  4. See the crash

Expected behavior

The game should not crash.

Screenshots and Video

Logs: ``` ixn@jammy:/tmp$ ~/.local/share/unvanquished/base/daemon Unvanquished 0.53.2 Linux x86_64 Sep 4 2022 cmdline: [FS] Lib path: /home/ixn/.local/share/unvanquished/base [FS] Home path: /home/ixn/.local/share/unvanquished [FS] Pak search path: /home/ixn/.local/share/unvanquished/base/pkg [FS] Pak search path: /home/ixn/.local/share/unvanquished/pkg Starting crash logging server [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/unvanquished_0.53.2.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/unvanquished_0.52.0.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/tex-common_2.2.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-players_0.53.0.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-players_0.52.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-legacy_0.52.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-weapons_0.53.0.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-weapons_0.52.1.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-weapons_0.52.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-buildables_0.53.0.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-buildables_0.52.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-voices_0.52.dpk'... [FS] Loading pak '/home/ixn/.local/share/unvanquished/base/pkg/res-soundtrack_0.52.dpk'... execing 'default.cfg' execing 'presets/input/wasd.cfg' Warn: Couldn't read conhistory: No such file or directory ----- Client Initialization ----- Loading RSA keys from pubkey Daemon RSA public-key found. ----- Client Initialization Complete ----- IP: 127.0.0.1 IP: 192.168.10.50 IP: 192.168.10.100 IP: 10.0.3.1 IP6: ::1 IP6: fe80::2ebd:a9a2:fa21:99c%enP4p65s0 Opening IP6 socket: [::]:* Opening IP socket: 0.0.0.0:* --- Common Initialization Complete --- Calling GetRefAPI… SDL_Init( SDL_INIT_VIDEO )... Using SDL version 2.0.12 SDL using driver "x11" Initializing OpenGL display Using GLEW version 2.2.0 Display aspect: 1.250 Display resolution: 1280x1024 ...setting mode -2: 1280×1024 Using preferred context - 24-bit OpenGL 2.1 compatibility OpenGL Renderer: Mali-G610 (Panfrost) Warn: Provided OpenGL 3.0 is not the same as requested 2.1 version Using GL3 Renderer in OpenGL 2.x mode... Available modes: '1280x1024 320x240 800x600 1024x768 1152x864 1280x960 720x480 640x400 1280x800 864x486 1024x576 1280x720 720x400 640x350 ' Detected graphics driver class 'integrated' Detected graphics hardware class 'generic' Initializing OpenGL extensions ...ignoring GL_ARB_debug_output ...found shading language version 130 ...using GL_ARB_half_float_pixel ...using GL_ARB_texture_float ...using GL_EXT_gpu_shader4 ...using GL_EXT_texture_integer ...using GL_ARB_texture_rg ...using GL_ARB_texture_gather ...using GL_EXT_texture_compression_s3tc ...using GL_ARB_texture_compression_rgtc ...using GL_EXT_texture_filter_anisotropic ...using GL_ARB_half_float_vertex ...using GL_ARB_framebuffer_object ...using GL_ARB_get_program_binary ...using GL_ARB_buffer_storage ...using GL_ARB_uniform_buffer_object ...using GL_ARB_map_buffer_range ...using GL_ARB_sync GL_VENDOR: Panfrost GL_RENDERER: Mali-G610 (Panfrost) GL_VERSION: 3.0 Mesa 23.0.0-devel (git-fd340d5154) GL_MAX_TEXTURE_SIZE: 8192 GL_SHADING_LANGUAGE_VERSION: 1.30 GL_MAX_VERTEX_UNIFORM_COMPONENTS 16352 GL_MAX_VERTEX_ATTRIBS 16 Occlusion query bits: 64 GL_MAX_DRAW_BUFFERS: 8 GL_TEXTURE_MAX_ANISOTROPY_EXT: 16.000000 GL_MAX_RENDERBUFFER_SIZE: 8192 GL_MAX_COLOR_ATTACHMENTS: 8 PIXELFORMAT: color(24-bits) MODE: -2, 1280 x 1024 fullscreen hz: N/A Using OpenGL version 3.0, requested: 2.1 Using OpenGL 2.x context. Using OpenGL extensions: GL_ARB_half_float_pixel GL_ARB_texture_float GL_EXT_gpu_shader4 GL_EXT_texture_integer GL_ARB_texture_rg GL_ARB_texture_gather GL_EXT_texture_compression_s3tc GL_ARB_texture_compression_rgtc GL_EXT_texture_filter_anisotropic GL_ARB_half_float_vertex GL_ARB_framebuffer_object GL_ARB_get_program_binary GL_ARB_buffer_storage GL_ARB_uniform_buffer_object GL_ARB_map_buffer_range GL_ARB_sync Using S3TC (DXTC) texture compression. Using GPU vertex skinning with max 256 bones in a single pass, models are hardware accelerated. ][ALSOFT] (EE) Failed to set real-time priority for thread: Operation not permitted (1) [ALSOFT] (EE) Failed to set real-time priority for thread: Operation not permitted (1) Extracting VM module cgame-x86_64.nexe from /home/ixn/.local/share/unvanquished/base/pkg/unvanquished_0.53.2.dpk... Loading VM module cgame-x86_64.nexe... Using loader args: /home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap /home/ixn/.local/share/unvanquished/base/nacl_loader --r_debug=0xXXXXXXXXXXXXXXXX --reserved_at_zero=0xXXXXXXXXXXXXXXXX -v -B /home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe -e -i 100:45 -- /home/ixn/.local/share/unvanquished/cgame-x86_64.nexe 100 Warn: Error during initialization: IPC: Socket closed by remote end Error during cgame shutdown: IPC: Failed to send message: Broken pipe Warn: VM exited with non-zero exit code 2 ixn@jammy:/tmp$ /home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap /home/ixn/.local/share/unvanquished/base/nacl_loader --r_debug=0xXXXXXXXXXXXXXXXX --reserved_at_zero=0xXXXXXXXXXXXXXXXX -v -B /home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe -e -i 100:45 -- /home/ixn/.local/share/unvanquished/cgame-x86_64.nexe 100 sel_ldr argument list: /home/ixn/.local/share/unvanquished/base/nacl_loader --r_debug=0x0000000000213000 --reserved_at_zero=0x0000000000000000 -v -B /home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe -e -i 100:45 -- /home/ixn/.local/share/unvanquished/cgame-x86_64.nexe 100 [48090,2293663616:21:20:52.368948] Error while loading "/home/ixn/.local/share/unvanquished/cgame-x86_64.nexe": Data Execution Prevention is required but is not supported [48090,2293663616:21:20:52.397326] NaClPerfCounterInterval(SelMain __start__:SnapshotBlob): 49539 microsecs [48090,2293663616:21:20:52.400980] NACL: Application output follows [48090,2293663616:21:20:52.401246] NaClAppStartModule: module not loaded Dumping vmmap. In PrintVmmap Done. ``` The important line appears to be this: `[48090,2293663616:21:20:52.368948] Error while loading "/home/ixn/.local/share/unvanquished/cgame-x86_64.nexe": Data Execution Prevention is required but is not supported`

System information:

Additional context

The check for DEP appears to be here:

https://source.chromium.org/chromium/chromium/src/+/main:native_client/src/trusted/platform_qualify/posix/nacl_dep_qualify.c;l=147;drc=c3304aefc16d3c021c637ea6edfd9a8ab750a2db

Sonicadvance1 commented 1 year ago

Looks like this is due to FEX not yet supporting No-execute bits. No way currently to work around this.

icecream95 commented 1 year ago

That does not appear to be the only problem:

The executable has symbols, so patching out the DEP check is fairly easy, but it still crashes in the same place:

echo -ne '\xb8\x01\x00\x00\x00\xc3' | dd of=~/.local/share/unvanquished/base/nacl_loader conv=notrunc bs=1 seek=$(nm -td ~/.local/share/unvanquished/base/nacl_loader | grep NaClAttemptToExecuteData$ | cut -d" " -f1)

If I run the NaCl executable standalone, it works:

$ ~/.local/share/unvanquished/base/nacl_helper_bootstrap ~/.local/share/unvanquished/base/nacl_loader --r_debug=0xXXXXXXXXXXXXXXXX --reserved_at_zero=0xXXXXXXXXXXXXXXXX -v -B ~/.local/share/unvanquished/base/irt_core-x86_64.nexe -e -i 100:45 -- ~/.local/share/unvanquished/cgame-x86_64.nexe 100 
sel_ldr argument list:
/home/ixn/.local/share/unvanquished/base/nacl_loader --r_debug=0x0000000000213000 --reserved_at_zero=0x0000000000000000 -v -B /home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe -e -i 100:45 -- /home/ixn/.local/share/unvanquished/cgame-x86_64.nexe 100
[48669,3164112768:22:54:19.521049] NaClPerfCounterInterval(SelMain __start__:SnapshotBlob): 19793 microsecs
[48669,3164112768:22:54:19.561419] NaClPerfCounterInterval(NaClAppLoadFile __start__:PreAllocAddrSpace): 6674 microsecs
[48669,3164112768:22:54:19.563309] Native Client module will be loaded at base address 0x0000007400000000
[48669,3164112768:22:54:19.563855] NaClPerfCounterInterval(NaClAppLoadFile PreAllocAddrSpace:*AllocAddrSpace): 2445 microsecs
[48669,3164112768:22:54:19.568757] NaClPerfCounterInterval(NaClAppLoadFile *AllocAddrSpace:*NaClElfImageLoad): 4896 microsecs
[48669,3164112768:22:54:19.633383] NaClPerfCounterInterval(NaClAppLoadFile *NaClElfImageLoad:*MakeDynText): 26119 microsecs
[48669,3164112768:22:54:19.845893] NaClPerfCounterInterval(NaClAppLoadFile *MakeDynText:*ValidateImg): 250998 microsecs
[48669,3164112768:22:54:19.854045] NaClPerfCounterInterval(NaClAppLoadFile __start__:EndLoadFile): 299192 microsecs
[48669,3164112768:22:54:19.855799] NaClPerfCounterInterval(SelMain SnapshotBlob:AppLoadEnd): 335242 microsecs
[48669,3164112768:22:54:19.868812] NaClPerfCounterInterval(NaClTextDyncodeCreate __start__:*DynRegionValidate): 6896 microsecs
[48669,3164112768:22:54:19.879332] NaClPerfCounterInterval(SelMain AppLoadEnd:BlobLoaded): 23534 microsecs
[48669,3164112768:22:54:19.879439] NACL: Application output follows
[48669,3164112768:22:54:19.908316] NaClPerfCounterInterval(SelMain BlobLoaded:CreateMainThread): 28970 microsecs

But the game still crashes:

GL_VENDOR: Panfrost 
GL_RENDERER: Mali-G610 (Panfrost) 
GL_VERSION: 3.0 Mesa 23.0.0-devel (git-fd340d5154) 
GL_MAX_TEXTURE_SIZE: 8192 
GL_SHADING_LANGUAGE_VERSION: 1.30 
GL_MAX_VERTEX_UNIFORM_COMPONENTS 16352 
GL_MAX_VERTEX_ATTRIBS 16 
Occlusion query bits: 64 
GL_MAX_DRAW_BUFFERS: 8 
GL_TEXTURE_MAX_ANISOTROPY_EXT: 16.000000 
GL_MAX_RENDERBUFFER_SIZE: 8192 
GL_MAX_COLOR_ATTACHMENTS: 8 
PIXELFORMAT: color(24-bits) 
MODE: -2, 1280 x 1024 fullscreen hz: N/A 
Using OpenGL version 3.0, requested: 2.1 
Using OpenGL 2.x context. 
Using OpenGL extensions: GL_ARB_half_float_pixel GL_ARB_texture_float GL_EXT_gpu_shader4 GL_EXT_texture_integer GL_ARB_texture_rg GL_ARB_texture_gather GL_EXT_texture_compression_s3tc GL_ARB_texture_compression_rgtc GL_EXT_texture_filter_anisotropic GL_ARB_half_float_vertex GL_ARB_framebuffer_object GL_ARB_get_program_binary GL_ARB_buffer_storage GL_ARB_uniform_buffer_object GL_ARB_map_buffer_range GL_ARB_sync 
Using S3TC (DXTC) texture compression. 
Using GPU vertex skinning with max 256 bones in a single pass, models are hardware accelerated. 
][ALSOFT] (EE) Failed to set real-time priority for thread: Operation not permitted (1)
[ALSOFT] (EE) Failed to set real-time priority for thread: Operation not permitted (1)
Extracting VM module cgame-x86_64.nexe from /home/ixn/.local/share/unvanquished/base/pkg/unvanquished_0.53.2.dpk...

Loading VM module cgame-x86_64.nexe... 
Using loader args:  /home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap /home/ixn/.local/share/unvanquished/base/nacl_loader --r_debug=0xXXXXXXXXXXXXXXXX --reserved_at_zero=0xXXXXXXXXXXXXXXXX -v -B /home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe -e -i 100:44 -- /home/ixn/.local/share/unvanquished/cgame-x86_64.nexe 100 
Warn: Error during initialization: IPC: Socket closed by remote end 
Error during cgame shutdown: IPC: Failed to send message: Broken pipe 
Warn: VM exited with non-zero exit code 2

Doing a diff on strace output shows that this is the problem:

<48654 openat(AT_FDCWD, "/home/ixn/.local/share/unvanquished/base/nacl_loader", O_RDONLY) = 3
>48550 openat(AT_FDCWD, "/home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap", O_RDONLY) = 3

So when run standalone, nacl_helper_bootstrap correctly loads from the nacl_loader file, but when launched by the game it loads the executable binary again and prints this error… so maybe command line arguments are getting read wrong?

bootstrap_helper: /home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap: ELF file not ET_DYN! e_type=2

Here is a good execve call:

48705 execve("/home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap", ["/home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap", "/home/ixn/.local/share/unvanquished/base/nacl_loader", "--r_debug=0xXXXXXXXXXXXXXXXX", "--reserved_at_zero=0xXXXXXXXXXXXXXXXX", "-v", "-B", "/home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe", "-e", "-i", "100:45", "--", "/home/ixn/.local/share/unvanquished/cgame-x86_64.nexe", "100"], 0x7fcd9e5130 /* 29 vars */) = 0

And a bad one:

48623 execve("/home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap", ["/home/ixn/.local/share/unvanquished/base/nacl_helper_bootstrap", "/home/ixn/.local/share/unvanquished/base/nacl_loader", "--r_debug=0xXXXXXXXXXXXXXXXX", "--reserved_at_zero=0xXXXXXXXXXXXXXXXX", "-v", "-B", "/home/ixn/.local/share/unvanquished/base/irt_core-x86_64.nexe", "-e", "-i", "100:45", "--", "/home/ixn/.local/share/unvanquished/cgame-x86_64.nexe", "100"], 0x7f89e08138 /* 0 vars */) = 0

Perhaps the difference in environment variable count is important?

Sonicadvance1 commented 1 year ago

Fancy, not sure why we would end up losing environment variables with our execve wrapping.

icecream95 commented 1 year ago

Hmm, even with env -i it works when run directly, so it can't be that.

The code to load the loader appears to be here:

https://source.chromium.org/chromium/chromium/src/+/main:native_client/src/trusted/service_runtime/linux/nacl_bootstrap.c;l=620

icecream95 commented 1 year ago

It appears that the problem is related to what file descriptors are open. If I close stdin with 0<&-, then I get the ET_DYN error. Wrapping the execution of the binary in the game by redirecting stdout to a file (normally it is closed) fixes the error there.

But even then things don't work right. I think it is just too slow, making the game time out:

Warn: Error during initialization: IPC: Timed out while waiting for VM message

Here is execution with timestamps for FEX:

[51642,2402649984:01:00:12.848724] NaClPerfCounterInterval(SelMain __start__:SnapshotBlob): 19097 microsecs
[51642,2402649984:01:00:12.888818] NaClPerfCounterInterval(NaClAppLoadFile __start__:PreAllocAddrSpace): 6611 microsecs
[51642,2402649984:01:00:12.890682] Native Client module will be loaded at base address 0x0000007400000000
[51642,2402649984:01:00:12.891220] NaClPerfCounterInterval(NaClAppLoadFile PreAllocAddrSpace:*AllocAddrSpace): 2411 microsecs
[51642,2402649984:01:00:12.895736] NaClPerfCounterInterval(NaClAppLoadFile *AllocAddrSpace:*NaClElfImageLoad): 4508 microsecs
[51642,2402649984:01:00:12.960252] NaClPerfCounterInterval(NaClAppLoadFile *NaClElfImageLoad:*MakeDynText): 25617 microsecs
[51642,2402649984:01:00:13.172942] NaClPerfCounterInterval(NaClAppLoadFile *MakeDynText:*ValidateImg): 251574 microsecs
[51642,2402649984:01:00:13.181098] NaClPerfCounterInterval(NaClAppLoadFile __start__:EndLoadFile): 298781 microsecs
[51642,2402649984:01:00:13.182867] NaClPerfCounterInterval(SelMain SnapshotBlob:AppLoadEnd): 334620 microsecs
[51642,2402649984:01:00:13.195832] NaClPerfCounterInterval(NaClTextDyncodeCreate __start__:*DynRegionValidate): 6856 microsecs
[51642,2402649984:01:00:13.206364] NaClPerfCounterInterval(SelMain AppLoadEnd:BlobLoaded): 23500 microsecs
[51642,2402649984:01:00:13.206478] NACL: Application output follows
[51642,2402649984:01:00:13.235486] NaClPerfCounterInterval(SelMain BlobLoaded:CreateMainThread): 29112 microsecs
[51642,2399237696:01:00:27.540030] Exit syscall handler: 255
[51642,2402649984:01:00:27.565823] NaClPerfCounterInterval(SelMain CreateMainThread:WaitForMainThread): 14330338 microsecs
[51642,2402649984:01:00:27.565932] NaClPerfCounterInterval(SelMain __start__:SelMainEnd): 14736797 microsecs

Note how it starts fast, but then it takes almost 15 seconds for the NaCl appliaction to exit. Compare with qemu, which is faster overall:

[35,15907520:11:58:27.509871] NaClPerfCounterInterval(SelMain __start__:SnapshotBlob): 4730 microsecs
[35,15907520:11:58:27.514665] NaClPerfCounterInterval(NaClAppLoadFile __start__:PreAllocAddrSpace): 1804 microsecs
[35,15907520:11:58:36.755350] Native Client module will be loaded at base address 0x0000007400000000
[35,15907520:11:58:36.785382] NaClPerfCounterInterval(NaClAppLoadFile PreAllocAddrSpace:*AllocAddrSpace): 9270705 microsecs
[35,15907520:11:58:36.789724] NaClPerfCounterInterval(NaClAppLoadFile *AllocAddrSpace:*NaClElfImageLoad): 4345 microsecs
[35,15907520:11:58:36.901574] NaClPerfCounterInterval(NaClAppLoadFile *NaClElfImageLoad:*MakeDynText): 111461 microsecs
[35,15907520:11:58:37.516854] NaClPerfCounterInterval(NaClAppLoadFile *MakeDynText:*ValidateImg): 615669 microsecs
[35,15907520:11:58:37.520299] NaClPerfCounterInterval(NaClAppLoadFile __start__:EndLoadFile): 10007393 microsecs
[35,15907520:11:58:37.520615] NaClPerfCounterInterval(SelMain SnapshotBlob:AppLoadEnd): 10010966 microsecs
[35,15907520:11:58:37.546541] NaClPerfCounterInterval(NaClTextDyncodeCreate __start__:*DynRegionValidate): 23221 microsecs
[35,15907520:11:58:37.550001] NaClPerfCounterInterval(SelMain AppLoadEnd:BlobLoaded): 29384 microsecs
[35,15907520:11:58:37.550051] NACL: Application output follows
[35,15907520:11:58:37.555085] NaClPerfCounterInterval(SelMain BlobLoaded:CreateMainThread): 4977 microsecs
[35,17475136:11:58:37.642341] Exit syscall handler: 255
[35,15907520:11:58:37.643620] NaClPerfCounterInterval(SelMain CreateMainThread:WaitForMainThread): 88533 microsecs
[35,15907520:11:58:37.643878] NaClPerfCounterInterval(SelMain __start__:SelMainEnd): 10138886 microsecs
icecream95 commented 1 year ago

The speed issue is fixed by disabling Multiblock for the nacl_helper_bootstrap process… and so now it works!

unvanquished

That 40fps is achieved at high settings, with CPU at about 20% on each of the big cores, and the Mali-G610 at 30% load… so it could be a lot better, but that isn't really FEX's fault. Thunking isn't even enabled.