jpy debug logging does not work well within interactive environments

[fabrice-ducos]

I observed this bug with an experimental JSR223 jpy interpreter, with the debug mode enabled (that corresponds to launching the JVM with -Djpy.debug=true as specified in the jpy 0.9.0 readthedocs manual)

I insist that this bug was not introduced by this new (and far from complete) interpreter (that is just a shell script based on the standard JDK jrunscript tool for JSR223 compliant implementations), but simply revealed by it. Here is how to reproduce the bug easily:

• clone or download the following jpy fork (it is simply jpy 0.12.0 with JSR223 support, not yet integrated to the official fork) and a jpyinterp.sh interpreter,
• cd to the repository
• build jpy: python setup.py build maven bdist_wheel
• launch the interpreter, first in normal mode, second in debug mode

In normal mode, everything behaves as expected:

$ ./jpyinterp.sh 
cpython> import math
None
cpython> print(math.pi)
3.141592653589793
None
cpython> 

In debug mode (-Djpy.debug=true), the evaluation of any python command (import, print, etc) ends up in an infinite loop (example below with import math)

$ ./jpyinterp.sh -Djpy.debug=true
org.jpy.PyLib: entered static initializer
org.jpy.PyLibConfig: entered static initializer
org.jpy.PyLibConfig: exited static initializer
org.jpy.PyLib: DL.dlopen("/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10/lib/python3.10/config-3.10-darwin/libpython3.10.dylib", DL.RTLD_GLOBAL + DL.RTLD_LAZY
org.jpy.PyLib: System.load("/Users/ducos/Projects/jpy/build/lib.macosx-12-x86_64-3.10/jpy.cpython-310-darwin.so")
org.jpy.PyLib: exited static initializer
org.jpy.PyLib: Starting Python with 2 extra module path(s):
org.jpy.PyLib:   /Users/ducos/Projects/jpy/build/lib.macosx-12-x86_64-3.10
org.jpy.PyLib:   /Users/ducos/Projects/jpy
PyLib_startPython: entered: jenv=0x7faba480d1f8, pyInit=0, JPy_Module=0x0
PyLib_startPython: global Python interpreter information:
  Py_GetProgramName()     = "python3"
  Py_GetPrefix()          = "/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10"
  Py_GetExecPrefix()      = "/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10"
  Py_GetProgramFullPath() = "/Users/ducos/.jenv/versions/1.8/bin/jrunscript"
  Py_GetPath()            = "/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10/lib/python310.zip:/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10/lib/python3.10:/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10/lib/python3.10/lib-dynload"
  Py_GetPythonHome()      = "(null)"
  Py_GetVersion()         = "3.10.1 (main, Dec  6 2021, 22:25:40) [Clang 13.0.0 (clang-1300.0.29.3)]"
  Py_GetPlatform()        = "darwin"
  Py_GetCompiler()        = "[Clang 13.0.0 (clang-1300.0.29.3)]"
  Py_GetBuildInfo()       = "main, Dec  6 2021, 22:25:40"
PyLib_startPython: exiting: jenv=0x7faba480d1f8, pyInit=1, JPy_Module=0x10fa66a20
cpython> import math
Java_org_jpy_PyLib_executeCode: code='import math'
Java_org_jpy_PyLib_executeInternal: using Java Map globals
Java_org_jpy_PyLib_executeInternal: using Java Map locals
Java_org_jpy_PyLib_executeInternal: copied back Java global
Java_org_jpy_PyLib_executeInternal: copied back Java locals
None
cpython> Java_org_jpy_PyLib_executeCode: code='dict()'
Java_org_jpy_PyLib_executeInternal: using main globals
Java_org_jpy_PyLib_executeInternal: using globals for locals
Java_org_jpy_PyLib_executeCode: code='def create_module(module_name, script):
  from importlib import util
  spec = util.spec_from_loader(module_name, loader=None)
  module = util.module_from_spec(spec)
  exec(script, module.__dict__)
  return module'
Java_org_jpy_PyLib_executeInternal: using main globals
Java_org_jpy_PyLib_executeInternal: using PyObject locals
PyLib_CallAndReturnObject: objId=0x10fa7c640, isMethodCall=1, name='__getitem__', argCount=1
PyLib_CallAndReturnObject: objId=0x10f8a3e20, isMethodCall=0, name='__call__', argCount=2
PyLib_CallAndReturnObject: objId=0x10fa7aed0, isMethodCall=0, name='identity', argCount=1
PyLib_CallAndReturnObject: objId=0x10f947390, isMethodCall=1, name='cleanupOnlyUseFromGIL', argCount=0
JMethod_InvokeMethod: calling Java method org.jpy.PyObjectReferences#cleanupOnlyUseFromGIL
PyLib_CallAndReturnObject: objId=0x10f947390, isMethodCall=1, name='cleanupOnlyUseFromGIL', argCount=0
JMethod_InvokeMethod: calling Java method org.jpy.PyObjectReferences#cleanupOnlyUseFromGIL
PyLib_CallAndReturnObject: objId=0x10f947390, isMethodCall=1, name='cleanupOnlyUseFromGIL', argCount=0

HINT: in order to see what ./jpyinterp.sh -D does, one can leverage the bash -x option:
$ bash -x ./jpyinterp.sh -Djpy.debug=true

On my system, it is equivalent to the following command (of course, paths will be different on another system):
jrunscript -Djpy.pyLib=/usr/local/Cellar/[email protected]/3.10.1/Frameworks/Python.framework/Versions/3.10/lib/python3.10/config-3.10-darwin/libpython3.10.dylib -Djpy.jpyLib=/Users/ducos/Projects/jpy/build/lib.macosx-12-x86_64-3.10/jpy.cpython-310-darwin.so -Djpy.jdlLib=/Users/ducos/Projects/jpy/build/lib.macosx-12-x86_64-3.10/jdl.cpython-310-darwin.so -cp target//jpy-0.12.0-SNAPSHOT.jar -l python -Djpy.debug=true

EDIT:
The bug occurs ONLY in interactive mode. It DOES NOT occur when executing a script, even in debug mode:
./jpyinterp.sh -Djpy.debug=true hello.py

(where hello.py is a simple file containg a print("Hello JPy") statement)

[devinrsmith]

I haven't run this myself, but I don't think it's an infinite loop - my guess is you could type something else in, hit enter, and it would "work" (you might not be able to clearly see what you are typing though). I think all the extra logging you are seeing is coming from a java thread that is always running and is responsible for ensuring objects get cleaned up.

That said, I definitely see how this is probably not what you want to happen in an interactive session. Ideally, you'd only see the debug activity from the commands you enter.

[fabrice-ducos]

Dear Devin,

I have just tested your assumption and it is perfectly right. It is still possible to type commands in the interpreter, but the output never ends spamming the screen. The commands keep being interpreted though.