"You called InitGoogleLogging() twice!" error on Embedded Blender as a Python Module

TL;DR

Hello, I’m using Blender as a Python module to automate the exportation of fbx files directly from Unity Editor. So far I’ve managed to put all the pieces together and I’m able to generate fbx files, but whenever Unity reloads the .net assemblies Google Logging library used by blender enters on an invalid state and eventually crashes.

Here is the log it generates before crashing:

Could not create logging file: Invalid argument
COULD NOT CREATE A LOGGINGFILE 20200521-153632.181824!Could not create logging file: Invalid argument
COULD NOT CREATE A LOGGINGFILE 20200521-153632.181824!Could not create logging file: Invalid argument
COULD NOT CREATE A LOGGINGFILE 20200521-153632.181824!Could not create logging file: Invalid argument
COULD NOT CREATE A LOGGINGFILE 20200521-153632.181824!F0521 15:36:32.549110 149480 utilities.cc:322] Check failed: !IsGoogleLoggingInitialized() You called InitGoogleLogging() twice!
*** Check failure stack trace: ***

Context

I have compiled Blender from branch blender-v2.82-release as a Python module and added it to an embedded Python on Unity Editor through Python.NET. I can access bpy from the Unity Editor.

I’ve had python running on Unity for quite a while now so I’m positive that the problem is directly related to adding the blender module to the equation.

Assembly Reloading

On the Unity Editor whenever there is a change in the c# script files Unity will recompile the .net assemblies, unload the old assemblies and then load the newly compiled assemblies.

Project File Structure

I chose to keep blender files in a separated folder to make it easy to track blender files from python files. During python initialization I add the proper folders to python_path and I also set the BLENDER_SYSTEM_SCRIPTS and BLENDER_SYSTEM_DATAFILES environment variables to the appropriate directories.

Project folder (cwd)
 |- Tools
     |- Python
     |   |- Lib/site-packages
     |   |- python37.zip
     |- Blender
         |- 2.82
         |   |- datafiles 
         |   |- scripts 
         |- bpy.pyd
         |- BlendThumb.dll
         |- tbbmalloc.dll 
         |- tbbmalloc_proxy.dll 

Pyhton Initialization Inside Unity

The following script is showing how I initialize and shutdown python from Unity. I also have to shutdown and re-initialize Python when the unity assemblies are reloaded. As the .net code I’m using is a wrapper around python37.dll I annotated the code with comments pointing to the relevant native calls to the python37.dll made by the .net wrapper.

    [InitializeOnLoadMethod]
    static void Initialize()
    { 
        AssemblyReloadEvents.beforeAssemblyReload += ShutdownPythonEngine;
        AssemblyReloadEvents.afterAssemblyReload += InitializePythonEngine;
        EditorApplication.quitting += ShutdownPythonEngine;
    }

    // called when Unity is open or assemblies are reload
    static void InitializePythonEngine()
    {
        Debug.Log("Initializing Python Engine...");
        var projectPath = Path.GetFullPath($@"{Application.dataPath}\..");
        var toolsPath = $@"{projectPath}\Tools";
        var logsPath = $@"{projectPath}\Logs\{Guid.NewGuid()}";
        
        var pythonHome = $@"{toolsPath}\Python";
        var blenderHome = $@"{toolsPath}\Blender";
        PythonEngine.PythonHome = pythonHome; 

        var pythonLib = $@"{pythonHome}\Lib";
        var pythonSitePackages = $@"{pythonHome}\Lib\site-packages";
        var pythonZip = $@"{pythonHome}\python37.zip";
        PythonEngine.PythonPath = $"{pythonZip};{pythonHome};{pythonLib};{pythonSitePackages};{blenderHome}";
        
        // set necessary blender environment variables 
        Environment.SetEnvironmentVariable("BLENDER_SYSTEM_SCRIPTS", $@"{blenderHome}\2.82\scripts");
        Environment.SetEnvironmentVariable("BLENDER_SYSTEM_DATAFILES", $@"{blenderHome}\2.82\datafiles");
        //Environment.SetEnvironmentVariable("GLOG_log_dir", logsPath); 
        
        PythonEngine.Initialize(); // loads python37.dll and initialize Python
        _threadsPtr = PythonEngine.BeginAllowThreads(); // Calls PyEval_SaveThread
    }
    

    // called when Unity is closed or before assemblies are reload
    static void ShutdownPythonEngine()
    {
        Debug.Log("Shutting Down Python Engine...");
        PythonEngine.EndAllowThreads(_threadsPtr); // calls PyEval_RestoreThread
        PythonEngine.Shutdown(); // calls Py_Finalize
    }

What I’ve done so far

I’ve done some digging in the blender source code and found that this error message is raised by the InitGoogleLoggingUtilities function on utilities.cc line 321 and there is also a ShutdownGoogleLoggingUtilities defined at line 337 of the same file that should be called on shutdown.

I’ve notticed that the InitGoogleLoggingUtilities is indirectly called by the libmv_initLogging function on logging.cc line 36 during initialization but I did not find any call to ShutdownGoogleLoggingUtilities on the code.

I believe that the error I’m getting is due to ShutdownGoogleLoggingUtilities not being called when bpy module is shutdown.

Does it make sense? If so, can this be fixed for future versions?

Also, since I’m using an earlier version of blender, what can I do to fix the problem on my end? Should I try and fix the code myself or there is anything else that can be done?

1 Like

Hi @garrafote.

I’m not really sure where to begin. This analysis is quite in depth, but I have never messed with the Unity Editor before. Also, setting the BLENDER_SYSTEM_SCRIPTS and BLENDER_SYSTEM_DATAFILES environment variables is unfamiliar territory for me. Usually, I just put the 2.82 folder in the “right place” and am off to the races. But that’s in “normal” Python.

That said… any time I have gotten:

Check failed: !IsGoogleLoggingInitialized() You called InitGoogleLogging() twice!

It was because the scripts directory was not in the place that bpy.so expected it.

That said, and given that you have gotten as far as you have gotten… I dunno! Is this a multi-threaded environment? People have had weird stuff happen on occasion with multithreading.

All that said, I hope you find a comprehensive resolution to your unique use case. Blender working in conjunction with development software like that would be a real dream come true. Good luck!

FYI, I can reproduce this by running an embedding the Python interpreter twice. E.g.

melis@juggle 08:25:~/software/blender-bpy-git$ cat t_embed.c 
#define PY_SSIZE_T_CLEAN
#include <Python.h>

int
main(int argc, char *argv[])
{
    wchar_t *program = Py_DecodeLocale(argv[0], NULL);
    if (program == NULL) {
        fprintf(stderr, "Fatal error: cannot decode argv[0]\n");
        exit(1);
    }
    Py_SetProgramName(program);  
    Py_Initialize();
    PyRun_SimpleString("import bpy\n");
    if (Py_FinalizeEx() < 0) {
        exit(120);
    }

    // One more time...
    
    Py_SetProgramName(program); 
    Py_Initialize();
    PyRun_SimpleString("import bpy\n");
    if (Py_FinalizeEx() < 0) {
        exit(120);
    }
    PyMem_RawFree(program);    
    return 0;
}

melis@juggle 08:26:~/software/blender-bpy-git$ gcc -o t_embed t_embed.c -I /usr/include/python3.8/ -lpython3.8

melis@juggle 08:27:~/software/blender-bpy-git$ ./t_embed 
F0522 08:25:08.797941  1623 utilities.cc:322] Check failed: !IsGoogleLoggingInitialized() You called InitGoogleLogging() twice!
*** Check failure stack trace: ***
    @     0x7f6423df93dd  google::LogMessage::Fail()
    @     0x7f6423dfdf6c  google::LogMessage::SendToLog()
    @     0x7f6423df90dd  google::LogMessage::Flush()
    @     0x7f6423df98c9  google::LogMessageFatal::~LogMessageFatal()
    @     0x7f6423e011ba  google::glog_internal_namespace_::InitGoogleLoggingUtilities()
    @     0x7f64238e0e3a  libmv_initLogging
    @     0x7f6422daf1de  main_python_enter
    @     0x7f642336b7d4  bpy_module_delay_init
    @     0x7f642336b83d  dealloc_obj_dealloc
    @     0x7f6427c52a71  PyDict_SetItem
    @     0x7f6427c52d6d  PyDict_SetItemString
    @     0x7f6427c5d37b  PyModule_AddObject
    @     0x7f6427d532ca  _PyImport_LoadDynamicModuleWithSpec
    @     0x7f6427d5365d  (unknown)
    @     0x7f6427c20397  (unknown)
    @     0x7f6427c19f80  PyVectorcall_Call
    @     0x7f6427cd2b20  _PyEval_EvalFrameDefault
    @     0x7f6427cbd8f4  _PyEval_EvalCodeWithName
    @     0x7f6427cbec7b  _PyFunction_Vectorcall
    @     0x7f6427cd180a  _PyEval_EvalFrameDefault
    @     0x7f6427cbea9d  _PyFunction_Vectorcall
    @     0x7f6427ccd58e  _PyEval_EvalFrameDefault
    @     0x7f6427cbea9d  _PyFunction_Vectorcall
    @     0x7f6427ccd14a  _PyEval_EvalFrameDefault
    @     0x7f6427cbea9d  _PyFunction_Vectorcall
    @     0x7f6427ccd14a  _PyEval_EvalFrameDefault
    @     0x7f6427cbea9d  _PyFunction_Vectorcall
    @     0x7f6427ccd14a  _PyEval_EvalFrameDefault
    @     0x7f6427cbea9d  _PyFunction_Vectorcall
    @     0x7f6427c346d0  (unknown)
    @     0x7f6427cac9fd  _PyObject_CallMethodIdObjArgs
    @     0x7f6427c04b61  PyImport_ImportModuleLevelObject
^CAborted (core dumped)

It does not occur when loading and then importlib.reload()ing the bpy module in a single Python interpreter session (although a bunch of other errors happen in that case).

Looking at the stack trace above the call to libmv_initLogging kicks off the error. So perhaps making libmv clean up the logging nicely on shutdown would be something to try to fix in your local copy of the code.

Hmmm, according to this glog issue:

AFAIK, dynamic libraries should not call any (third party) initialization routines. Instead, this should be application’s responsibility (in the main ). Only this way the order of initialization routines can be specified. By following this rule, most of the problems can be avoided.

Looking at source/creator/creator.c the call to InitGoogleLogging is indirectly made from main(). Interestingly that particular piece reads

#ifdef WITH_LIBMV
  libmv_initLogging(argv[0]);
#elif defined(WITH_CYCLES_LOGGING)
  CCL_init_logging(argv[0]);
#endif

So if libmv isn’t configured in then CCL_init_logging would be called, which actually also calls InitGoogleLogging. When the standalone module version of Blender is built the code uses a hack to turn main into main_python_enter, which is then called from bpy_module_delay_init() in source/blender/python/intern/bpy/_interface.c. Plus there seems to be a bit of hackery going on to get the bpy module initialized (I’m not very familiar with the code, btw).

But I guess the real issue is that the Unity process stays alive while Python.Net is reloaded, causing the logging function to be executed too many times. To do it right Unity itself should initialize the logging and the init calls in bpy should be disabled. At least, that’s the hack I would try first in this case.

@PaulMelis nice! good to know the issue is not singular to my use case.

In my case unity does not use Glog and according to their changelog we could theoretically init and shutdown multiple times:

  • Now users can re-initialize glog after ShutdownGoogleLogging
    […]
  • Add ShutdownGoogleLogging to close syslog (thanks DGunchev)

I saw that libmv doesn’t seem to have a shutdown pair to libmv_initLogging so I went ahead and added a libmv_shutdownLogging and called it on main_python_exit:

// logging.cc
void libmv_shutdownLogging() {
  google::ShutdownGoogleLogging();
}

// creator.c
#ifdef WITH_PYTHON_MODULE
void main_python_exit(void)
{ 
#ifdef WITH_LIBMV                                                                                                      
  libmv_shutdownLogging();                                                                                             
#endif                                                                                                                 
  WM_exit_ex((bContext *)evil_C, true);
  evil_C = NULL;
}

But after compiling and testing again I got a segmentation fault, which leads me to believe that there could be other issues involved.

(I’ll post the crash log in a bit)

One more thing, on your embedding code shouldn’t you be calling Py_Finalize before the second call to 'Py_Initialize ?

There’s a call to Py_FinalizeEx(), should do more-or-less the same.

oops I’m embarrassed I didn’t see that… my bad,

Anyway here is the stack trace on the segmentation fault:

Stack Trace of Crashed Thread 15976:
0x00007FFF77015048 (python37) PyDict_GetItem
0x00007FFF700A8AD2 (bpy) PyInit_bpy
0x00007FFF700A8CB6 (bpy) PyInit_bpy
0x00007FFF700A8F23 (bpy) PyInit_bpy
0x00007FFF7009DC82 (bpy) PyInit_bpy
ERROR: SymGetSymFromAddr64, GetLastError: 'Attempt to access invalid address.' (Address: 00007FFF7009B934)
0x00007FFF7009B934 (bpy) (function-name not available)
ERROR: SymGetSymFromAddr64, GetLastError: 'Attempt to access invalid address.' (Address: 00007FFF6FDEC406)
0x00007FFF6FDEC406 (bpy) (function-name not available)
ERROR: SymGetSymFromAddr64, GetLastError: 'Attempt to access invalid address.' (Address: 00007FFF6FC1F89C)
0x00007FFF6FC1F89C (bpy) (function-name not available)
0x00007FFF7009BDD4 (bpy) PyInit_bpy
0x00007FFF77017476 (python37) PyObject_GenericSetAttrWithDict
0x00007FFF770302C3 (python37) PyModule_AddObject
0x00007FFF76FF1418 (python37) Py_Main
0x00007FFF76FF1283 (python37) Py_Main
0x00007FFF76FF11E9 (python37) Py_Main
0x00007FFF77020880 (python37) PyMethodDef_RawFastCallDict
0x00007FFF7702804F (python37) PyEval_EvalFrameDefault
0x00007FFF7701E3AC (python37) PyEval_EvalCodeWithName
0x00007FFF7701DC0C (python37) PyFunction_FastCallDict
0x00007FFF770253B8 (python37) PyEval_EvalFrameDefault
0x00007FFF7701DAF1 (python37) PyFunction_FastCallDict
0x00007FFF77024574 (python37) PyEval_EvalFrameDefault
0x00007FFF7701DAF1 (python37) PyFunction_FastCallDict
0x00007FFF77024B5E (python37) PyEval_EvalFrameDefault
0x00007FFF7701DAF1 (python37) PyFunction_FastCallDict
0x00007FFF77024B5E (python37) PyEval_EvalFrameDefault
0x00007FFF7701DAF1 (python37) PyFunction_FastCallDict
0x00007FFF77024B5E (python37) PyEval_EvalFrameDefault
0x00007FFF7701D624 (python37) PyFunction_FastCallDict
0x00007FFF7700D297 (python37) PyObject_CallMethodIdObjArgs
0x00007FFF7700D15D (python37) PyObject_CallMethodIdObjArgs
0x00007FFF7704494E (python37) PyBytes_Fini
0x00007FFF7700D040 (python37) PyImport_ImportModuleLevelObject
0x00007FFF770414FD (python37) PyUnicodeWriter_Init
0x00007FFF77041419 (python37) PyUnicodeWriter_Init
0x00007FFF77062D58 (python37) PyErr_NoMemory
0x0000021F23182983 (Python.Runtime) Python.Runtime.Runtime.PyObject_Call()
0x0000021F281F7A43 (Python.Runtime) Python.Runtime.ImportHook.__import__()
0x0000021F2318DA1B (Python.Runtime) Python.Runtime.ImportHook.__import__()
0x00007FFF77020893 (python37) PyMethodDef_RawFastCallDict
0x00007FFF77020626 (python37) PyObject_FastCallDict
0x00007FFF77072D34 (python37) PyErr_NoMemory
0x00007FFF7701E3AC (python37) PyEval_EvalCodeWithName
0x00007FFF7702B573 (python37) PyEval_EvalCodeEx
0x00007FFF7702B4D1 (python37) PyEval_EvalCode
0x0000021F3A33DCF3 (Python.Runtime) Python.Runtime.Runtime.PyEval_EvalCode()
0x0000021F3A33DB93 (Python.Runtime) Python.Runtime.PyScope.Execute()
0x0000021F3A33DA73 (Python.Runtime) Python.Runtime.PyScope.Execute()
0x0000021F3A3386B3 (Assembly-CSharp-Editor) DefaultNamespace.BlenderUtility.GetScenes()

Not sure if it helps

To get rid of all the glog stuff I rebuilt the bpy module with WITH_CYCLES_LOGGING and WITH_LIBMV set to OFF. This fixes some of the issues, but still gives a segfault on the second interpreter doing import bpy, this time related to materials (in my case). I think there’s a lot of places in the Blender code where this kind of double initialization is not going the work. The code simply isn’t written to handle this use case.

Edit: assertion triggered:

BLI_assert failed: /home/melis/c/blender-git/source/blender/blenkernel/intern/material.c:87, material_init_data(), at '(BLI_memory_is_zero((const char *)(material) + ((((const char *)&((material)->id)) - ((const char *)(material))) + sizeof((material)->id)), sizeof(*(material)) - ((((const char *)&((material)->id)) - ((const char *)(material))) + sizeof((material)->id))))'

While it may be possible to fix Blender for this case, likely quite a few of Blender’s library dependencies will have the same problem (including Numpy). Which then in turn would need to be fixed as well.

This seems unlikely to happen anytime soon.

1 Like

I’m likely hitting the same segfault on my end but I can’t easily get debug info.

Thank you for the help, I’ve decided I’m going to call blender in a separate background process instead.

It’s interesting that I had python (python.net) working fine on unity for a while now. I guess it must be that luckily I didn’t load any troubling module until now.