Failure to start JVM with jpype 1.5.1 on Windows

[villares]

With 1.5.0 on this env I could start the JVM.

C:\Users\alexandre.villares>python
Python 3.10.11 (tags/v3.10.11:7d4cc5a, Apr  5 2023, 00:38:17) [MSC v.1929 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import jpype
>>> jpype.__version__
'1.5.0'
>>> jpype.startJVM()
Picked up JAVA_TOOL_OPTIONS: -Djava.vendor="Sun Microsystems Inc."
>>> jpype.getDefaultJVMPath()
'C:\\Users\\alexandre.villares\\Downloads\\thonny-4.1.6-portable\\user_data\\jdk-17\\bin\\server\\jvm.dll'
>>>

Updating to jpype 1.5.1 it fails:

C:\Users\alexandre.villares>python -m pip install jpype1 --upgrade
Requirement already satisfied: jpype1 in c:\users\alexandre.villares\downloads\thonny-4.1.6-portable\lib\site-packages (1.5.0)
Collecting jpype1
  Downloading jpype1-1.5.1-cp310-cp310-win_amd64.whl.metadata (5.0 kB)
Requirement already satisfied: packaging in c:\users\alexandre.villares\downloads\thonny-4.1.6-portable\lib\site-packages (from jpype1) (24.2)
Downloading jpype1-1.5.1-cp310-cp310-win_amd64.whl (356 kB)
Installing collected packages: jpype1
  Attempting uninstall: jpype1
    Found existing installation: JPype1 1.5.0
    Uninstalling JPype1-1.5.0:
      Successfully uninstalled JPype1-1.5.0
  WARNING: Failed to remove contents in a temporary directory 'C:\Users\alexandre.villares\AppData\Local\Temp\pip-uninstall-lxb7b830'.
  You can safely remove it manually.
Successfully installed jpype1-1.5.1

C:\Users\alexandre.villares>python
Python 3.10.11 (tags/v3.10.11:7d4cc5a, Apr  5 2023, 00:38:17) [MSC v.1929 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import jpype
>>> jpype.__version__
'1.5.1'
>>> jpype.startJVM()
Picked up JAVA_TOOL_OPTIONS: -Djava.vendor="Sun Microsystems Inc."
Error occurred during initialization of VM
Could not find agent library instrument on the library path, with error: Can't find dependent libraries
Module java.instrument may be missing from runtime image.

C:\Users\alexandre.villares>python
Python 3.10.11 (tags/v3.10.11:7d4cc5a, Apr  5 2023, 00:38:17) [MSC v.1929 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import jpype
>>> jpype.getDefaultJVMPath()
'C:\\Users\\alexandre.villares\\Downloads\\thonny-4.1.6-portable\\user_data\\jdk-17\\bin\\server\\jvm.dll'
>>>

[Thrameos]

Do you happen to know the path to the org.jpype.jar? If it is locatable and on the path, then the next issue is why java.instrument is missing.

[villares]

Do you happen to know the path to the org.jpype.jar? If it is locatable and on the path, then the next issue is why java.instrument is missing.

I'll try to find out (I don't have access to Windows at home) and I'll report!

[villares]

Maybe some new information!

I have reproduced the issue on another machine. org.jpype.jar in both 1.5.0 and 1.5.1 is present at:
C:\Users\abav\Downloads\thonny-4.1.6-portable\Lib\site-packages\org.jpype.jar

Python 3.10.11 (C:\Users\abav\Downloads\thonny-4.1.6-portable\python.exe)
>>> import jpype
>>> jpype.__version__
'1.5.0'
>>> jpype.getDefaultJVMPath()
'C:\\Users\\abav\\Downloads\\thonny-4.1.6-portable\\user_data\\jdk-17\\bin\\server\\jvm.dll'
>>> jpype.startJVM()
>>> 

Then:

Python 3.10.11 (C:\Users\abav\Downloads\thonny-4.1.6-portable\python.exe)
>>> import jpype
>>> jpype.__version__
'1.5.1'
>>> jpype.getDefaultJVMPath()
'C:\\Users\\abav\\Downloads\\thonny-4.1.6-portable\\user_data\\jdk-17\\bin\\server\\jvm.dll'
>>> jpype.startJVM()
Error occurred during initialization of VM
Could not find agent library instrument on the library path, with error: Can't find dependent libraries
Module java.instrument may be missing from runtime image.

Process ended with exit code 1.
────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
Python 3.10.11 (C:\Users\abav\Downloads\thonny-4.1.6-portable\python.exe)
>>> 

Fiddling around I noticed jpype.startJVM() worked fine if I didn't set JAVA_HOME and jpype found jre-1.8

Python 3.10.11 (C:\Users\abav\Downloads\thonny-416-plain\python.exe)
>>> import jpype
>>> jpype.getDefaultJVMPath()
'C:\\Program Files\\Java\\jre-1.8\\bin\\server\\jvm.dll'
>>> jpype.startJVM()
>>> 

So I moved my jdk-17 to a similar place, and it worked!

Python 3.10.11 (C:\Users\abav\Downloads\thonny-416-plain\python.exe)
>>> import jpype
>>> jpype.getDefaultJVMPath()
'C:\\Program Files\\Java\\jdk-17\\bin\\server\\jvm.dll'
>>> jpype.startJVM()
>>>

Now.... what is wrong with the previous jdk-17 path? I have no idea and I hope you can figure out!

[Thrameos]

It sounds like someone has shipped a partial copy of the JVM. There are lots of reasons that that can happen, though there is never a guarantee we will run without a full JVM. It must be JE only version. I will have to have to make some options to catch that case.

[Thrameos]

It seems like the best plan would be to make agent an option rather than the default and add logic to specifically add org.jpype to the classpath automatically. Our original solution was bad because our module was a second class citizen cause we were never loaded into the main system class loader. This always presented a problem because I run my testing with org.jpype on the classpath which meant I was constantly getting better results than typical runs. I tried to rectify this by loading as agent which has the huge advantage that we guarantee to load first, and we can register ourselves as the controlling module. Running as an agent is a privileged position, but it requires java.instrumentation module which apparently some distributions are shipping without. The problem is that we have thus created a new requirement and someone is shipping out stripped down copies of the JVM. Stripped down copies are for light installs and typically used when you are serving just one application thus you know in advance all the classes that need to be provided. There was NEVER a guarantee that JPype will run with a stripped down JVM. It is always subject to breakage because at any time we may add a new call to org.jpype and if stripped down JVM doesn’t have it then it will fail. So the logic choice is try to get everything working as a first class citizen and do a 1.5.2 release. I am guessing a month or so depending on my availability over the holidays. In the meantime either 1.5.0 or if Python 3.13 is required then we must use a full copy of the OpenJDK.

[ryanmkurtz]

I just did a bit of testing and it seems the problem is actually occurring on a full OpenJDK from https://jdk.java.net/23/. This is not the distro I typically use but I bet a lot of people do.

UPDATE: Actually something else weird might be going on in my case....OpenJDK may be fine after all.

[ryanmkurtz]

The real issue is looking like a conflict between 2 different versions of Java being used at the same time...one on the PATH, and a different one on JAVA_HOME.

[astrelsky]

I may have an appropriate fix. It seems to be an issue that has been present in jpype for a long time and the changes in 1.5.1 just only caused it to appear. I'll give it a go tonight.

[ryanmkurtz]

A temporary workaround that I've confirmed works is to ensure that your JAVA_HOME matches the Java that is on your path. I'm guessing that those don't match for everyone this isn't working for.

[Thrameos]

@ryanmkurtz Please test with #1245

@astrelsky I put a PR that fixes it on my side, but as I still don't know the exact origin of the problem there are still questions. I am going to also take a shot at the non-ascii path issue in the same go.

[ryanmkurtz]

I can test on Friday.

[stulacy]

A temporary workaround that I've confirmed works is to ensure that your JAVA_HOME matches the Java that is on your path. I'm guessing that those don't match for everyone this isn't working for.

In case it's useful, although it looks like it's been solved, but this wasn't the case for me.

PS C:\Users\sl561
> echo $Env:JAVA_HOME
C:\Users\sl561\AppData\Local\Programs\Microsoft\jdk-11.0.25.9-hotspot

PS C:\Users\sl561
> which java
/c/Users/sl561/AppData/Local/Programs/Microsoft/jdk-11.0.25.9-hotspot/bin/java

[Thrameos]

I also see reports of some failures on osx. So clearly there is more than one issue. We are currently guessing:

1. partial jvm installs (missing instrumentation)
2. conflicted jvm (path and java_path mismatch)

We have two PR addressing these. Hopefully there isn't a third.

[ryanmkurtz]

Just doing a quick check in on the progress of JPype 1.5.2 to address this issue.

[ryanmkurtz]

I also see reports of some failures on osx. So clearly there is more than one issue. We are currently guessing:

1. partial jvm installs (missing instrumentation)
2. conflicted jvm (path and java_path mismatch)

We have two PR addressing these. Hopefully there isn't a third.

I think case 1 is a red herring, as this example shows:

[grauchs]

I have an issue with jpype. In a python console, the command jpype.startJVM(path-to-jvm.dll) leads to a crash of the python console without any error message. I am using Windows 10 Enterprise, version 22H2 and python 3.10.8. This crash happens in jpype 1.5.2 and 1.5.1.

When I downgrade to jpype 1.5.0, the jvm starts normally with jpype.startJVM(path-to-jvm.dll), both for the jvm.dll provided by openJDK-18.0.2.1 and COMSOL 62. However, if I add the classpath parameter, or define the CLASSPATH environment variable, python crashes again without any error message. In case I give the parameter classpath='', or no CLASSPATH defined, the jvm starts normally.

After reading through the issues, I checked the following:

• this happens with the openJDK's jvm.dll (openJdK 18.0.2.1) and with COMSOL6.2 jvm.dll, so a stripped-down version of the dlls provided should not be the issue.
• all loaded dlls (listed by dumpbin /dependents), python.exe etc are x64, according to dumpbin /headers. The Windows 10 version is x64.
• python, jpype and openJDK's jvm.dll have the same file permissions, Comsol's doesn't, so this should also not be the issue.
• all versions of jpype (1.5.0, 1.5.1 and 1.5.2) successfully pass the C++ program testJVM.exe, so all dll's should be present.
• JAVA_HOME is included in PATH.
• the classpath parameter is only checked for the COMSOL jvm.dll, and is taken from the definition of the python module mph, so the parameter definition should be ok.
• since I am new to jpype (and mph), I cannot say that this behaviour is related to a Windows upgrade!

Any idea why the classpath of CLASSPATH triggers a python crash without error message? As this is a computer at my workplace, could security settings (which I cannot change) be to blame?

[Thrameos]

You would need to catch the crash in a debugger to be sure. 1.5.1 attempted to use the java agent which was a problem for some systems but 1.5.2 rolled that back.

It could be that jpype us triggering something in the jvm that is causing a crash or that jpype is triggering something in the C++. But without a line number there us nothing to go on.

[grauchs]

Here is the information given by the IDLE debugger at the point python crashes. It uses jpype-1.5.0. The full python command of the calling code reads:
jpype.startJVM('c:\program files\comsol\comsol62\multiphysics\java\win64\jre\bin\server\jvm.dll', classpath='c:\program files\comsol\comsol62\multiphysics\plugins')

Here is the debugger output:

with jpype-1.5.2, jpype.startJVM, called without classpath parameter and no CLASSPATH environment variable set, fails at the same location according to the debugger.

For completeness, COMSOL 6.2 is shipped with
openjdk version "11.0.22" 2024-01-16
OpenJDK Runtime Environment Temurin-11.0.22+7 (build 11.0.22+7)
OpenJDK 64-Bit Server VM Temurin-11.0.22+7 (build 11.0.22+7, mixed mode)

[Thrameos]

It appears that crash occurred when something released a lock in the importlib bootstrap layer. We are going to need to nail it down to the line in C++ which lead to that call and then examine the code above .

Please review doc/develguide.rst on the section "Tracing" it will allow you to build a tracing version which will write a log file of which methods were hit. If the method is large and there are no TRACE commands then add traces as needed to isolate the crash point.

[Thrameos]

As for the most likely cause. It must be a reference counting error in JPype. Python wasn't great about its bookkeeping for certain reference counts particularly with modules. They are trying to close that gap but it tends to exposed bugs in Python modules where something assumed the reference counter was held and it wasn't. But this is only a theory.

[grauchs]

Here is what I obtain for jpype-1.5.2 compiled with --enable-tracing. The command jpype.startJVM('c:...) in the test script produces the following output (i did not include the large output before the call to this method):

PyJPModule_startup
JPPyUnicode::asStringUTF8
< JPPyUnicode::asStringUTF8
PyJPModule_startup: vmpath c:\program files\comsol\comsol62\multiphysics\java\win64\jre\bin\server\jvm.dll
JPPyUnicode::asStringUTF8
< JPPyUnicode::asStringUTF8
PyJPModule_startup: arg -Djava.class.path=C:\Program Files\Python310\lib\site-packages\org.jpype.jar
JPContext::startJVM
JPContext::startJVM: Convert strings 0
JPContext::startJVM: Load entry points
> JPContext::loadEntryPoints
> Win32PlatformAdapter::loadLibrary
< Win32PlatformAdapter::loadLibrary
< JPContext::loadEntryPoints
JPContext::startJVM: Pack arguments
JPContext::startJVM: IgnoreUnrecognized 0
JPContext::startJVM: NumOptions 1
JPContext::startJVM: Option -Djava.class.path=C:\Program Files\Python310\lib\site-packages\org.jpype.jar
JPContext::startJVM: Create JVM
JPContext::startJVM: JVM created

The script does of course not finish, with python crashing.

[Thrameos]

So the next step would to be find the location of the last error message and add additional trace statements until we pin down the fault point. Most likely in the resource creation section as we are past the jvm start.

[Thrameos]

The other possibility us the start jvm actually failed in some unexpected way and we didn't catch it. I do not see a leave startJVM so in must be a child of the block itself. I also don't see an exception so either this block lacks exception handling or no exception was thrown.

Currently it appears to be failing in line 205 to 215. So we need to add a JP_TRACE_IN at 205 and a JP_TRACE_OUT at the end on JPContext::initializeResources. Then add JP_TRACE statements in front of each of the statements leading up to 216. If you are not comfortable with the mods I can make a PR for testing.

The three statements in that area are critical to starting as they create the handles for exception processing. They are unchecked currently as we don't yet have the safety system for exception handling in place. On the other hand these statements should never fail or it would indicate something is fatally wrong with the JVM.

In other words the most we can accomplish here is tell the user something failed (ie unable to get class java.lang.Throwable) and then gracefully exit telling them the jvm is broken. Unfortunately I have no clue how a jvm can be broken like that. But lets start by confirming the fatal point then look at the differences between the two versions to nail it down.

You may want add compile 1.5.0 with tracing as well so you have a successful trace to compare to.

[grauchs]

Here is the trace output of the modified method:
JPContext::startJVM: Create JVM
JPContext::startJVM: JVM created
JPContext::startJVM: JVM created check
which corresponds to the this portion of code of the startJVM method in file jp_context.cpp:
// Launch the JVM
JNIEnv* env = nullptr;
JP_TRACE("Create JVM");
try
{
CreateJVM_Method(&m_JavaVM, (void**) &env, (void*) &jniArgs);
} catch (...)
{
JP_TRACE("Exception in CreateJVM?");
}
JP_TRACE("JVM created");
JP_TRACE("JVM created check");
delete [] jniArgs.options;
JP_TRACE("delete jniArgs");

so the error should occur in the line "delete [] jniArgs.options;", provided no screen output got stuck in a buffer.

[Thrameos]

That line should not fail as we are just deleting memory created a few lines ago. I recommend trying a few fixes.

1. add +1 to the number of options allocated (ie new JavaVMOption[jniArgs.nOptions+1]) to see if the jvm has exceeded the memory space.
2. Drop the delete and see if we proceed with leaky memory.
3. diff 1.5.0 to 1.5.2 to see if we have a change we can roll back.

[grauchs]

I put the jp_trace_in and jp_trace_out into the initializeResources method, and the test run produced no further output, so it seems (to me) that the call of this method is never reached.

I try tracing version 1.5.0

[Thrameos]

Good. That confirms the problem is one of two locations.

1. the cleanup or handling if the arguments.
2. the launch point of the JPContext::loadEntryPoints which was changed to support non-ASIC jvms failing and leaving us in a bad state.

[grauchs]

That line should not fail as we are just deleting memory created a few lines ago. I recommend trying a few fixes.

1. add +1 to the number of options allocated (ie new JavaVMOption[jniArgs.nOptions+1]) to see if the jvm has exceeded the memory space.

ad 1.: no change in behaviour!

2. Drop the delete and see if we proceed with leaky memory.

ad 2.: test script runs until the end, i.e. successful completion!

3. diff 1.5.0 to 1.5.2 to see if we have a change we can roll back.

[grauchs]

I tested a tracing version of jpype-1.5.0:

• as mentioned above, jpype.startJVM without classpath parameter finishes successfully
• jpype.startJVM with classpath parameter behaves exactly like jpype-1.5.2, i.e. crashes at the "delete [] jniArgs.options;" command, and commenting out this line makes the testscript finish successfully.

[Thrameos]

Okay I think I missed something. I was assuming it worked in 1.5.0 but failed in 1.5.2. If it also failed in 1.5.0 then I don't need to consider the changes to be fault. (This should have been its own bug report as this is clearly not the same issue.)

I will have to analyze that section of the code. Perhaps we should just change the memory usage there to use malloc and free rather than new and delete.

[grauchs]

To avoid any misunderstandings, here is the condensed information about failing/succesfull runs of the testscript:

• with the command "delete [] jniArgs.options;" commented out, both jpype-1.5.0 and 1.5.2 finish successfully, with or without the classpath parameter given in the interface of method jpype.startJVM.

• with the command "delete [] jniArgs.options;" active, jpype-1.5.2 crashes at this command, with or without the classpath parameter given.

• with the command "delete [] jniArgs.options;" active, jpype-1.5.0 crashes at this command if the classpath parameter is given. jpype-1.5.0 finishes successfully at this command if the classpath parameter is omitted and the CLASSPATH environment variable is not defined. If the CLASSPATH environment variable is defined, even if it is only '', jpype-1.5.0 crashes at the delete command if no classpath parameter is given in the interface of method jpype.startJVM.

[Thrameos]

I have enough information to formulate an alterative. I will send you a PR to test when it is complete.