search

ValveSoftware / openvr

OpenVR SDK
http://steamvr.com
BSD 3-Clause "New" or "Revised" License
6.07k stars 1.28k forks source link

(Beta 2.2.1) OpenXR call failed with result XR_ERROR_CALL_ORDER_INVALID (Linux) #1804

Open WhitleyStriber opened 9 months ago

WhitleyStriber commented 9 months ago

I'm currently developing an app on Unreal Engine and receive this error when trying to launch VR preview more than once. I would LOVE to be on Linux to create my game, but this issue makes it impossible for any developer to create games on Linux.

I am able to launch the VR preview once and debug the game just fine in VR, but when I launch it a 2nd time, this callstack and error log gets printed to console:

[2023.12.14-13.05.09:410][968]LogAudioMixerSDL: Opening default audio device (device index -1)
[2023.12.14-13.05.09:411][968]LogAudioMixer: Display: Using Audio Hardware Device USB Audio S/PDIF Output
[2023.12.14-13.05.09:411][968]LogAudioMixer: Display: Initializing Sound Submixes...
[2023.12.14-13.05.09:411][968]LogAudioMixer: Display: Creating Master Submix 'MasterSubmixDefault'
[2023.12.14-13.05.09:411][968]LogAudioMixer: Display: Creating Master Submix 'MasterReverbSubmixDefault'
[2023.12.14-13.05.09:412][968]LogAudioMixer: Display: Output buffers initialized: Frames=1024, Channels=6, Samples=6144, InstanceID=3
[2023.12.14-13.05.09:412][968]LogAudioMixer: Display: Starting AudioMixerPlatformInterface::RunInternal(), InstanceID=3
[2023.12.14-13.05.09:412][968]LogInit: FAudioDevice initialized with ID 3.
[2023.12.14-13.05.09:412][968]LogAudio: Display: Audio Device (ID: 3) registered with world 'VRTemplateMap'.
[2023.12.14-13.05.09:412][968]LogAudioMixer: Initializing Audio Bus Subsystem for audio device with ID 3
[2023.12.14-13.05.09:434][968]LogSlate: Updating window title bar state: overlay mode, drag disabled, window buttons hidden, title bar hidden
Ensure condition failed: ((Result) >= 0) [File:./../Plugins/Runtime/OpenXR/Source/OpenXRHMD/Private/OpenXRHMD.cpp] [Line: 1787] 
OpenXR call failed with result XR_ERROR_CALL_ORDER_INVALID
[2023.12.14-13.05.09:480][968]LogOutputDevice: Warning: 

Script Stack (0 frames) :

[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff04c073b35 Dladdr: 0.025130ms Open: 0.011850ms Search: 0.013760ms
[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff04c07258e Dladdr: 0.002020ms Open: 0.004559ms Search: 0.014550ms
[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff0914ad322 Dladdr: 0.073219ms Open: 0.005620ms Search: 0.028680ms
[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff0914aa50e Dladdr: 0.062399ms Open: 0.003270ms Search: 0.020450ms
[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff09149e88c Dladdr: 0.051660ms Open: 0.003570ms Search: 0.025599ms
[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff0914a06c8 Dladdr: 0.049390ms Open: 0.003419ms Search: 0.025470ms
[2023.12.14-13.05.09:480][968]LogCore: 0x00007ff0914a7f37 Dladdr: 0.040169ms Open: 0.003230ms Search: 0.023220ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff09149c68d Dladdr: 0.042719ms Open: 0.003300ms Search: 0.028010ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff09149be15 Dladdr: 0.040269ms Open: 0.003660ms Search: 0.024840ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff090c83286 Dladdr: 0.072639ms Open: 0.003320ms Search: 0.026039ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff091939631 Dladdr: 0.070039ms Open: 0.003470ms Search: 0.024840ms
[2023.12.14-13.05.09:481][968]LogCore: 0x0000000000242ce1 Dladdr: 0.001810ms Open: 0.006960ms Search: 0.015419ms
[2023.12.14-13.05.09:481][968]LogCore: 0x000000000024ecf9 Dladdr: 0.000890ms Open: 0.002950ms Search: 0.017860ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff09bbe5b31 Dladdr: 0.000480ms Open: 0.004020ms Search: 0.009170ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff08f2569c9 Dladdr: 0.010930ms Open: 0.002590ms Search: 0.000620ms
[2023.12.14-13.05.09:481][968]LogCore: 0x00007ff08f256a84 Dladdr: 0.008790ms Open: 0.002200ms Search: 0.000080ms
[2023.12.14-13.05.09:481][968]LogCore: 0x0000000000238508 Dladdr: 0.001370ms Open: 0.003380ms Search: 0.015660ms
[2023.12.14-13.05.09:481][968]LogStats: FPlatformStackWalk::StackWalkAndDump -  0.001 s
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: === Handled ensure: ===
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: 
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: Ensure condition failed: ((Result) >= 0)  [File:./../Plugins/Runtime/OpenXR/Source/OpenXRHMD/Private/OpenXRHMD.cpp] [Line: 1787] 
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: OpenXR call failed with result XR_ERROR_CALL_ORDER_INVALID
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: Stack: 
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff04c073b36 libUnrealEditor-OpenXRHMD.so!FOpenXRHMD::OnStereoStartup() [/mnt/horde/++UE5/Sync/Engine/Source/./../Plugins/Runtime/OpenXR/Source/OpenXRHMD/Private/OpenXRHMD.cpp:1787]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff04c07258f libUnrealEditor-OpenXRHMD.so!FOpenXRHMD::EnableStereo(bool) [/mnt/horde/++UE5/Sync/Engine/Source/./../Plugins/Runtime/OpenXR/Source/OpenXRHMD/Private/OpenXRHMD.cpp:841]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff0914ad323 libUnrealEditor-UnrealEd.so!UEditorEngine::GeneratePIEViewportWindow(FRequestPlaySessionParams const&, int, FWorldContext const&, EPlayNetMode, UGameViewportClient*, FSlatePlayInEditorInfo&) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:3451]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff0914aa50f libUnrealEditor-UnrealEd.so!UEditorEngine::CreateInnerProcessPIEGameInstance(FRequestPlaySessionParams&, FGameInstancePIEParameters const&, int) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:3082]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff09149e88d libUnrealEditor-UnrealEd.so!UEditorEngine::OnLoginPIEComplete_Deferred(int, bool, FString, FPieLoginStruct) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:1585]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff0914a06c9 libUnrealEditor-UnrealEd.so!UEditorEngine::CreateNewPlayInEditorInstance(FRequestPlaySessionParams&, bool, EPlayNetMode) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:1845]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff0914a7f38 libUnrealEditor-UnrealEd.so!UEditorEngine::StartPlayInEditorSession(FRequestPlaySessionParams&) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:2866]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff09149c68e libUnrealEditor-UnrealEd.so!UEditorEngine::StartQueuedPlaySessionRequestImpl() [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:1150]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff09149be16 libUnrealEditor-UnrealEd.so!UEditorEngine::StartQueuedPlaySessionRequest() [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/PlayLevel.cpp:1062]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff090c83287 libUnrealEditor-UnrealEd.so!UEditorEngine::Tick(float, bool) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/EditorEngine.cpp:1810]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff091939632 libUnrealEditor-UnrealEd.so!UUnrealEdEngine::Tick(float, bool) [/mnt/horde/++UE5/Sync/Engine/Source/./Editor/UnrealEd/Private/UnrealEdEngine.cpp:528]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x0000000000242ce2 UnrealEditor!FEngineLoop::Tick() [/mnt/horde/++UE5/Sync/Engine/Source/./Runtime/Launch/Private/LaunchEngineLoop.cpp:5819]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x000000000024ecfa UnrealEditor!GuardedMain(char16_t const*) [/mnt/horde/++UE5/Sync/Engine/Source/./Runtime/Launch/Private/Launch.cpp:190]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff09bbe5b32 libUnrealEditor-UnixCommonStartup.so!CommonUnixMain(int, char**, int (*)(char16_t const*), void (*)()) [/mnt/horde/++UE5/Sync/Engine/Source/./Runtime/Unix/UnixCommonStartup/Private/UnixCommonStartup.cpp:269]
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff08f2569ca libc.so.6!UnknownFunction(0x239c9)
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x00007ff08f256a85 libc.so.6!__libc_start_main(+0x84)
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: [Callstack] 0x0000000000238509 UnrealEditor!_start()
[2023.12.14-13.05.09:481][968]LogOutputDevice: Error: 
[2023.12.14-13.05.09:486][968]LogStats:                SubmitErrorReport -  0.000 s
[2023.12.14-13.05.09:497][968]LogStats:                    SendNewReport -  0.012 s
[2023.12.14-13.05.09:497][968]LogStats:             FDebug::EnsureFailed -  0.017 s
[2023.12.14-13.05.09:497][968]LogLoad: Game class is 'VRGameMode_C'
[2023.12.14-13.05.09:499][968]LogWorld: Bringing World /Game/VRTemplate/Maps/UEDPIE_0_VRTemplateMap.VRTemplateMap up for play (max tick rate 0) at 2023.12.14-08.05.09
[2023.12.14-13.05.09:499][968]LogWorld: Bringing up level for play took: 0.001376
[2023.12.14-13.05.09:499][968]LogOnline: OSS: Created online subsystem instance for: :Context_2
[2023.12.14-13.05.09:500][968]LogSlate: New Slate User Created. Platform User Id 8, User Index 8, Is Virtual User: 1
[2023.12.14-13.05.09:500][968]LogSlate: Slate User Registered.  User Index 8, Is Virtual User: 1
[2023.12.14-13.05.09:502][968]PIE: Server logged in
[2023.12.14-13.05.09:503][968]PIE: Play in editor total start time 0.501517 seconds.
[2023.12.14-13.05.09:515][968]LogViewport: Scene viewport resized to 422x1406, mode Windowed.
Resizing viewport due to setres change, 422 x 1406
[2023.12.14-13.05.09:528][969]LogViewport: Scene viewport resized to 349x1260, mode Windowed.
LogICUInternationalization: ICU TimeZone Detection - Raw Offset: -5:00, Platform Override: ''
LogInit: ExecutableName: CrashReportClient
LogInit: Build: ++UE5+Release-5.3-CL-29314046
LogInit: Engine Version: 5.3.2-29314046+++UE5+Release-5.3
LogInit: Compatible Engine Version: 5.3.0-27405482+++UE5+Release-5.3
LogInit: Net CL: 27405482
LogInit: OS: Gentoo Linux (6.6.2-gentoo-dist), CPU: AMD Ryzen 9 7950X 16-Core Processor, GPU: NVIDIA GeForce RTX 3080 Ti (NVIDIA UNIX x86_64 Kernel Module  545.29.06  Thu Nov 16 01:59:08 UTC 2023)
LogInit: Compiled (64-bit): Nov  3 2023 16:27:17
LogInit: Architecture: x64
LogInit: Compiled with Clang: 16.0.6 (github.com/llvm/llvm-project 7cbf1a2591520c2491aa35339f227775f4d3adf6)
LogInit: Build Configuration: Shipping
LogInit: Branch Name: ++UE5+Release-5.3
LogInit: Command Line:  -Abslog="/home/drew/.config/Epic/UnrealEngine/5.3/Saved/Logs/Mirage-CRC.log" -Unattended "/home/drew/.config/Epic/UnrealEngine/5.3/Saved/Crashes/ensureinfo-Mirage-pid-31633-8841973F9CA44493951EC3DA80BA57F8/"
LogInit: Base Directory: /home/drew/Games/Engine/Binaries/Linux/
LogInit: Allocator: Mimalloc
LogInit: Installed Engine Build: 1
LogInit: This binary is optimized with LTO: no, PGO: no, instrumented for PGO data collection: no
LogInit: Presizing for max 100000 objects, including 0 objects not considered by GC, pre-allocating 0 bytes for permanent pool.
LogInit: Object subsystem initialized
mmrrqq commented 8 months ago

I just ran into the same behavior using beta 2.3.1 and noticed that the SteamVR info panel still shows Now Playing <your_ue_project_name> when exiting the first VR preview window. The VR View is reset though.

The web console provides the following logs when exiting the VR preview from Unreal:

xrclient_UnrealEditorTue Jan 16 2024 11:01:46.048152 [Info] - Transitioning XrSession from XR_SESSION_STATE_VISIBLE to XR_SESSION_STATE_SYNCHRONIZED
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.048224 [Info] - Transitioning XrSession from XR_SESSION_STATE_SYNCHRONIZED to XR_SESSION_STATE_STOPPING
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.052675 [Info] - Transitioning XrSession from XR_SESSION_STATE_STOPPING to XR_SESSION_STATE_IDLE
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.052733 [Info] - Transitioning XrSession from XR_SESSION_STATE_IDLE to XR_SESSION_STATE_EXITING
vrserverTue Jan 16 2024 11:01:46.053251 [Info] - [OpenXR] No manifest. Clearing input data: system.generated.openxr.<my_UE_project_name>.unrealeditor.
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.072028 [Info] - Changing app type from VRApplication_OpenXRScene to VRApplication_OpenXRInstance
vrserverTue Jan 16 2024 11:01:46.072113 [Info] - AppInfoManager.ProcessQuit processid=15117 eLaunchingApp=LaunchingApp_None
vrserverTue Jan 16 2024 11:01:46.072151 [Info] - AppInfoManager.ProcessQuit: Clearing application system.generated.openxr.<my_UE_project_name>.unrealeditor PID was 15117
vrserverTue Jan 16 2024 11:01:46.072169 [Info] - AppInfoManager.ProcessQuit: Clearing application system.generated.openxr.<my_UE_project_name>.unrealeditor PID because 15117 has exited
vrserverTue Jan 16 2024 11:01:46.072267 [Info] - AppInfoManager.ProcessConnected BEGIN 15117 /home/mrothgaenger/dev/Linux_Unreal_Engine_5.3.2/Engine/Binaries/Linux/UnrealEditor 9 system.generated.openxr.<my_UE_project_name>.unrealeditor
vrserverTue Jan 16 2024 11:01:46.072307 [Info] - SetApplicationPid appkey=system.generated.openxr.<my_UE_project_name>.unrealeditor pid=15117, external transition
vrserverTue Jan 16 2024 11:01:46.072337 [Info] - SetApplicationPid: Setting app system.generated.openxr.<my_UE_project_name>.unrealeditor PID to 15117
vrserverTue Jan 16 2024 11:01:46.072376 [Info] - AppInfoManager.ProcessConnected END
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.072102 [Info] - Received message of type 1107 when 121 was expected on pipe VR_ServerPipe_12824
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.072129 [Warning] - IPC failure changing app type
xrclient_UnrealEditorTue Jan 16 2024 11:01:46.072153 [Error] - Unexpected error while trying to change the OpenXR application type: [VRInitError_Init_Internal]

and the following when trying to start the preview again:

xrclient_UnrealEditorTue Jan 16 2024 11:03:00.858994 [Info] - Initializing CVulkanVRRenderer
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.859068 [Info] - Debug markers: disabled, missing extension support. Is the Renderdoc layer enabled?
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.911567 [Info] - Initialized Vulkan transfer ring buffer, mapped at offset 0x0x7efd78000000.
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.912170 [Error] - Client connection in an invalid state [10], while attempting to transition application to VrApplication_OpenXRScene.
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.928290 [Info] - Changing app type from VRApplication_OpenXRScene to VRApplication_OpenXRInstance
vrserverTue Jan 16 2024 11:03:00.928462 [Info] - Refusing to change app type from 15117: UnrealEditor transition from VRApplication_OpenXRInstance to VRApplication_OpenXRInstance is illegal
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.928550 [Info] - Discarding sequence mismatched message type: 121, sequence: 446, expected type: 121, expected sequence: 447, pipe: VR_ServerPipe_12824
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.928597 [Warning] - ChangeAppType failed with VRInitError_Init_IllegalTypeTransition
xrclient_UnrealEditorTue Jan 16 2024 11:03:00.928665 [Error] - Unexpected error while trying to change the OpenXR application type: [VRInitError_Init_IllegalTypeTransition]