Packaged builds with BLUI on 4.12, 4.13 and 4.14 hang for over 60 seconds when run

[davidcollodi]

I'm using the latest BLUI release 'BLUI.3.1.Windows.Linux.CX.-.VS2015.zip' (dated 2.6.2016) on a Blank Project in UE 4.13.2 (though I've also tried this on 4.12.5 and 4.14.1). The project will compile without issue and run correctly in the editor. When I package the project (either for Development or Shipping), running the executable will cause a hang for around 60 seconds before the application launches. It appears the application fails to launch, but does appear around a minute later. This happens both on Windows 10 and Windows 8 machines. This issue does not happen for me on UE 4.11.2. Looking at the task manager - I see 3 Unreal processes start. Eventually one of the processes goes away before the application launches. Using the Launch button in the Unreal Editor, I've reproduced the issue and captured the following logging:

LogPlayLevel: Project.Run: ********** RUN COMMAND STARTED **********
LogPlayLevel: Project.RunInternal: Starting Client....
LogPlayLevel: CommandUtils.Run: Run: D:\Data\Documents\Unreal Projects\Test_4_13\Saved\StagedBuilds\WindowsNoEditor\Test_4_13\Binaries\Win64\Test_4_13.exe ../../../Test_4_13/Test_4_13.uproject /Game/StarterContent/Maps/Minimal_Default -stdout -abslog="C:\Users\dcoll\AppData\Roaming\Unreal Engine\AutomationTool\Logs\D+Applications+Epic+Games+4.13\Client.log" 
-Messaging -nomcp -Windowed -CrashForUAT -SessionId=6B3E1358408D650C80F114891C5BFD7B -SessionOwner="dcoll" -SessionName="Launch On Device"
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: LogCore:Error: Found 5 threads running, expected: -1073742360.
LogPlayLevel: Test_4_13: LogCore:Display: Dumping all worker threads to log.
LogPlayLevel: Test_4_13: LogCore:Display: Stack for thread 11740:
LogPlayLevel: Test_4_13: LogCore:Display:   ntdll.dll
LogPlayLevel: Test_4_13: LogCore:Display:   KERNELBASE.dll
LogPlayLevel: Test_4_13: LogCore:Display:   Test_4_13.exe!FCrashReportingThread::Run()
LogPlayLevel: Test_4_13: LogCore:Display:   KERNEL32.DLL
LogPlayLevel: Test_4_13: LogCore:Display:   ntdll.dll
LogPlayLevel: Test_4_13: LogCore:Display:   ntdll.dll
LogPlayLevel: Test_4_13: LogCore:Warning: A thread may have been injected but no culprit was found!
LogPlayLevel: Test_4_13: LogInit:Display: RandInit(231645113) SRandInit(231645114).LogModuleManager:Warning: ModuleManager: Module 'XMPP' not found - its StaticallyLinkedModuleInitializers function is null.
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [1108/133517:ERROR:tcp_socket_win.cc(361)] bind() returned an error: Only one usage of each socket address (protocol/network address/port) is normally permitted. (0x2740)
LogPlayLevel: Test_4_13: [1108/133517:ERROR:devtools_http_handler_impl.cc(307)] Cannot start http server for devtools. Stop devtools.
LogPlayLevel: Test_4_13: LogModuleManager:Warning: ModuleManager: Module 'XMPP' not found - its StaticallyLinkedModuleInitializers function is null.LogInit:Display: Game Engine Initialized.
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.18:310][  0]LogInit:Display: Game Engine Initialized.LogInit:Display: Starting Game.
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.18:318][  0]LogInit:Display: Starting Game.LogGameMode:Display: Match State Changed from EnteringMap to WaitingToStart
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.20:693][  0]LogGameMode:Display: Match State Changed from EnteringMap to WaitingToStartLogGameMode:Display: Match State Changed from WaitingToStart to InProgress
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.20:693][  0]LogGameMode:Display: Match State Changed from WaitingToStart to InProgressLogWindowsTextInputMethodSystem:Display: IME system now deactivated.
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.31:198][608]LogWindowsTextInputMethodSystem:Display: IME system now deactivated.LogOnline:Display: Unloading online subsystem: NULL
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.32:768][609]LogOnline:Display: Unloading online subsystem: NULLLogHttp:Display: Http module shutting down, but needs to wait on 1 outstanding Http requests:
LogPlayLevel: Test_4_13:
LogPlayLevel: Test_4_13: [2016.11.08-18.35.32:774][609]LogHttp:Display: Http module shutting down, but needs to wait on 1 outstanding Http requests:LogHttp:Display:  verb=[POST] url=[https://datarouter.ol.epicgames.com/datarouter/api/v1/public/data?SessionID=%7B4D965E7B-4296-6EB4-5CF1-2DB108A1A8C2%7D&AppID=UEGame.Rocket.Release%7C09886D134A6B9F8BC7047E9CA6D8
07DB%7CUE4Game&AppVersion=4.13.2-3172292%2B%2B%2BUE4%2BRelease-4.13&UserID=ANON-%7B4C2D118E-4E85-FDCA-1E44-3FA100A28155%7D&AppEnvironment=datacollector-binary&UploadType=eteventstream] status=Processing
LogPlayLevel: Test_4_13:
LogPlayLevel: Project.Run: ********** RUN COMMAND COMPLETED **********
LogPlayLevel: Automation.Execute: BUILD SUCCESSFUL
LogPlayLevel: Completed Launch On Stage: Run Task, Time: 96.362197
LogPlayLevel: Program.Main: AutomationTool exiting with ExitCode=0 (Success)
LogPlayLevel: Completed Launch On Stage: Post Launch Task, Time: 0.000007
LogPlayLevel: Launch On Completed. Time: 130.147942

[davidcollodi]

One ammendment to the original description - I did use the later source code with the 'GetModuleFilenames' fix to allow compilation in the build. Comparing the log with 4.11.2 logs, the major issue seems to be the apparent crash reported with the rather unhelpful core logging:

LogPlayLevel: Test_4_13: LogCore:Error: Found 5 threads running, expected: -1073742360.
LogPlayLevel: Test_4_13: LogCore:Display: Dumping all worker threads to log.
LogPlayLevel: Test_4_13: LogCore:Display: Stack for thread 11740:
LogPlayLevel: Test_4_13: LogCore:Display:   ntdll.dll
LogPlayLevel: Test_4_13: LogCore:Display:   KERNELBASE.dll
LogPlayLevel: Test_4_13: LogCore:Display:   Test_4_13.exe!FCrashReportingThread::Run()
LogPlayLevel: Test_4_13: LogCore:Display:   KERNEL32.DLL
LogPlayLevel: Test_4_13: LogCore:Display:   ntdll.dll
LogPlayLevel: Test_4_13: LogCore:Display:   ntdll.dll
LogPlayLevel: Test_4_13: LogCore:Warning: A thread may have been injected but no culprit was found!

[littlerussian]

Hi there!

I just want to confirm the issue, I'm experiencing it too. It appeared when we switched from 4.11 to 4.12 version.

Any further clue that you find might be helpful. I'll try to investigate the cause as well.

In my case, when I run the "Debug" build, the output hangs after this log:

Microsoft C++ exception: xSharedMemoryException at memory location 0x000000DC18CCEB80.

[davidcollodi]

I have found at least a temporary workaround for this problem - though not one that necessarily points to the root cause. If I build the UE4 Engine (in this case 4.13.2) myself from source instead of using Epic's pre-built engine, this hang/crash does not happen on package releases. I've only tried this for the 4.13.2 build thus far, so I don't know if it helps for others, but it may be worth a try.

[littlerussian]

Good to know, I'll give a try with 4.12 version. Maybe we should point it directly to Epic, although I don't know how to put the problem .

[davidcollodi]

Let me know if it works for you with the 4.12 build. If so, then it might be worth bringing up with Epic.
Since their release appears to work with most other plugins, and since the actual BLUI source looks fairly innocuous, I'd guess it was some sort of mismatch between the Unreal Engine and the CEF used by BLUI. But who knows, maybe this is some sort of obscure build issue with UE that doesn't happen when built locally?

[littlerussian]

You might be right about some mismatch in the dll, I think it could be related to allocators. I also tried with another CEF, the one shipped with unreal, that you can find here:

C:\Program Files (x86)\Epic Games\4.12\Engine\Binaries\ThirdParty\CEF3\Win64

If you merely replace the dlls you see the exact same behaviour. Maybe they have the same problem.

When I pause my debugger during the hang, I see it is stuck here:

IDelegateInstance* DelegateInstanceInterface = Super::GetDelegateInstanceProtectedHelper(DelegateBase);

in the file

C:\Program Files (x86)\Epic Games\4.12\Engine\Source\Runtime\Core\Public\Delegates\DelegateSignatureImpl_Variadics.inl

Is it the same for you?

[littlerussian]

FIXED!

I think I found a code solution that does not require building unreal engine from source code. I'll make a pull request in the following days.

If you want to fix it try this:

in BluManager.h, replace the static variables

static CefSettings settings; static CefMainArgs main_args;

with local variables, and modify Blu.cpp to use them accordingly, for example like this:

`

      CefString realExePath = *ExecutablePath;

    // Make a new manager instance
    CefRefPtr<BluManager> BluApp = new BluManager();

    // Set the sub-process path
    CefString(&BluApp->settings.browser_subprocess_path).FromString(realExePath);

    // Set the cache path
    CefString(&BluApp->settings.cache_path).FromString(GameDirCef);

    //CefExecuteProcess(BluManager::main_args, BluApp, NULL);
    CefInitialize(BluApp->main_args, BluApp->settings, BluApp, NULL);

    UE_LOG(LogBlu, Log, TEXT(" STATUS: Loaded"));`

I hope that it helps.

[davidcollodi]

Brilliant - great job! I'll try that in my code.

[davidcollodi]

Tried it in my build and it fixed my issue as well.

[Dannington]

As a real c++ dummy. I've tried this and failed, probably due to not understanding how to make the local variables. I tried just removing the 'static' from the start of the variables but it's just not compiling. I'd love a nudge in the right direction!

[davidcollodi]

Here is my StartupModule() function:

    /** IModuleInterface implementation */
    virtual void StartupModule() override
    {
        CefString GameDirCef = *FPaths::ConvertRelativePathToFull(FPaths::GameDir() + "BluCache");
        FString ExecutablePath = FPaths::ConvertRelativePathToFull(FPaths::GameDir() + "Plugins/BLUI/ThirdParty/cef/");
        // Make the CefSettings and CefMainArgs local as they only need to be used in this function
        CefSettings settings;
        CefMainArgs main_args;

        // Setup the default settings for BluManager
        settings.windowless_rendering_enabled = true;
        settings.no_sandbox = true;
        settings.remote_debugging_port = 7777;

    #if PLATFORM_LINUX
        ExecutablePath = "./blu_ue4_process";
    #endif
    #if PLATFORM_MAC
        ExecutablePath += "Mac/shipping/blu_ue4_process.app/Contents/MacOS/blu_ue4_process";
    #endif
    #if PLATFORM_WINDOWS
        ExecutablePath += "Win/shipping/blu_ue4_process.exe";
    #endif

        CefString realExePath = *ExecutablePath;

        // Set the sub-process path
        CefString(&settings.browser_subprocess_path).FromString(realExePath);

        // Set the cache path
        CefString(&settings.cache_path).FromString(GameDirCef);

        // Make a new manager instance
        CefRefPtr<BluManager> BluApp = new BluManager();

        //CefExecuteProcess(BluManager::main_args, BluApp, NULL);
        CefInitialize(main_args, settings, BluApp, NULL);

        UE_LOG(LogBlu, Log, TEXT(" STATUS: Loaded"));
    }

The only real change is that the settings and main_args variables and now declared in this function, as opposed to statically outside of it. Getting rid of the originals in BluManager.h and using these instead should work. I can't remember if there were other changes I needed to make (I don't think so) - but let me know if it's not working.

[Dannington]

Hi David, thanks so much for that - I only had to comment out a couple of references to those static variables at the bottom of BluManager.cpp

I can't tell you how much I appreciate the help with that! The reference in the code to the remote debugging port is interesting - have you used it? I've tried going to localhost:7777 in my chrome browser but it doesn't seem to connect.

Cheers!

[SrGeneroso]

Thanks a lot for the work to keep alive blui, I think this plugin deserves an epic grant.

2017-02-26 20:56 GMT+01:00 Dannington notifications@github.com:

Hi David, thanks so much for that - I only had to comment out a couple of references to those static variables at the bottom of BluManager.cpp

I can't tell you how much I appreciate the help with that! The reference in the code to the remote debugging port is interesting - have you used it? I've tried going to localhost:7777 in my chrome browser but it doesn't seem to connect.

Cheers!

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/AaronShea/BLUI/issues/89#issuecomment-282582195, or mute the thread https://github.com/notifications/unsubscribe-auth/AFSPonEkHMpp_bzS_y5-7qB0hqbkB4-gks5rgdjhgaJpZM4KsyWH .

[sightlinechristoffer]

So relieving to get this workaround (if that is what it is), good job there! I have kind of suspected that there is a clash between UE4 using port 7777 and CEF using the same port for debugging, but I'm just guessing.

But when changing the settings.remote_debugging_port = 7777 to another port the remote debugger seems to be working fine, so perhaps that is for the same reason?