Skip to content

It also means our exception handling is poor as exceptions escaping the context are quietly swallowed. #221

New issue
New issue
Closed
Closed
It also means our exception handling is poor as exceptions escaping the context are quietly swallowed.#221

Description

@behrica
behrica
opened on Sep 27, 2022
    It also means our exception handling is poor as exceptions escaping the context are quietly swallowed.

Originally posted by @cnuernber in #219 (comment)

Activity

  1. behrica commented on Sep 27, 2022

    @behrica
    behrica
    on Sep 27, 2022
    ContributorAuthor

    Just to not forget it.

    I am bitten hardly by this now, as this type of error make the code hang, and no exception is printed.
    It can be easily reproduced y running in embed a script which tried to load a "non existing python module".

    If I run it in "embedded mode", the below exception is not visible, and the python+JVM hangs for ever.
    I do see it, when running the same code in "non-embedded".

    {:clojure.main/message
 "Syntax error compiling at (src/crash.clj:12:1).\nModuleNotFoundError: No module named 'not existing'\n\n",
 :clojure.main/triage
 {:clojure.error/phase :compile-syntax-check,
  :clojure.error/line 12,
  :clojure.error/column 1,
  :clojure.error/source "crash.clj",
  :clojure.error/path "src/crash.clj",
  :clojure.error/class java.lang.Exception,
  :clojure.error/cause
  "ModuleNotFoundError: No module named 'not existing'\n"},
 :clojure.main/trace
 {:via
  [{:type clojure.lang.Compiler$CompilerException,
    :message
    "Syntax error compiling at (/home/carsten/Dropbox/sources/predict_disaster_tweet/src/crash.clj:12:1).",
    :data
    {:clojure.error/phase :compile-syntax-check,
     :clojure.error/line 12,
     :clojure.error/column 1,
     :clojure.error/source
     "/home/carsten/Dropbox/sources/predict_disaster_tweet/src/crash.clj"},
    :at [clojure.lang.Compiler load "Compiler.java" 7652]}
   {:type java.lang.Exception,
    :message "ModuleNotFoundError: No module named 'not existing'\n",
    :at
    [libpython_clj2.python.ffi$check_error_throw
     invokeStatic
     "ffi.clj"
     708]}],
  :trace
  [[libpython_clj2.python.ffi$check_error_throw
    invokeStatic
    "ffi.clj"
    708]
   [libpython_clj2.python.ffi$check_error_throw invoke "ffi.clj" 706]
   [libpython_clj2.python$import_module invokeStatic "python.clj" 165]
   [libpython_clj2.python$import_module invoke "python.clj" 158]
   [train$eval14176 invokeStatic "crash.clj" 12]
   [train$eval14176 invoke "crash.clj" 12]
   [clojure.lang.Compiler eval "Compiler.java" 7181]
   [clojure.lang.Compiler load "Compiler.java" 7640]
   [clojure.lang.Compiler loadFile "Compiler.java" 7578]
   [clojure.main$load_script invokeStatic "main.clj" 475]
   [clojure.main$script_opt invokeStatic "main.clj" 535]
   [clojure.main$script_opt invoke "main.clj" 530]
   [clojure.main$main invokeStatic "main.clj" 664]
   [clojure.main$main doInvoke "main.clj" 616]
   [clojure.lang.RestFn applyTo "RestFn.java" 137]
   [clojure.lang.Var applyTo "Var.java" 705]
   [clojure.main main "main.java" 40]],
  :cause "ModuleNotFoundError: No module named 'not existing'\n",
  :phase :compile-syntax-check}}

  2. behrica commented on Sep 27, 2022

    @behrica
    behrica
    on Sep 27, 2022
    ContributorAuthor

    I was not sure, if the fix would be here or in cljbridge,
    so I opened this before:

    behrica/clojurebridge#2

  3. behrica commented on Sep 27, 2022

    @behrica
    behrica
    on Sep 27, 2022
    ContributorAuthor

    behrica/clojurebridge#2 has some code snippets to reproduce it

  4. behrica commented on Sep 29, 2022

    @behrica
    behrica
    on Sep 29, 2022
    ContributorAuthor

    @cnuernber
    Could you have a look at this ?
    I am not able to dig myself, too much native and macro magic for me.

    Each time my code hangs, I am always wondering if there was a python exception, which I just don't see.

  5. jjtolton commented on Sep 29, 2022

    @jjtolton
    jjtolton
    on Sep 29, 2022
    Contributor

    @behrica can you provide a little more context? "ModuleNotFoundError: No module named 'not existing' is a Python error, but 'not existing' is a very unusual module name. I feel like I would need more information to pinpoint why the error is not printing to the console, because I don't think I'd be able to reproduce this.

  6. behrica commented on Sep 29, 2022

    @behrica
    behrica
    on Sep 29, 2022
    ContributorAuthor

    It happnes with "any exception" on python side, if using embedded mode and loading a script:

    crash.clj;

    (ns train
  (:require [libpython-clj2.python :refer [py.- py.] :as py]
            [libpython-clj2.python.ffi :as ffi]))
            ;; [libpython-clj2.require :refer [require-python]]
            ;; [libpython-clj2.python.gc]
(println "-------- manual-gil: " ffi/manual-gil)

(def locked (ffi/lock-gil))
(println :gil-locked)

(println :before-crash)
(py/import-module "not existing")  ;; whatever error on python side, like loading an non existing library
(println "crash fininished")

    Load the file in embedded:

    python -c 'from clojurebridge import cljbridge;cljbridge.load_clojure_file(clj_file="crash.clj",mvn_local_repo="/home/carsten/.m2/repository")'

  7. behrica commented on Sep 29, 2022

    @behrica
    behrica
    on Sep 29, 2022
    ContributorAuthor

    It "hangs" forever without printing any error

  8. cnuernber commented on Sep 29, 2022

    @cnuernber
    cnuernber
    on Sep 29, 2022
    Collaborator

    This appears to me to be an issue with clojurebridge, not libpython-clj. Specifically javabridge's static call pathway must swallow exceptions.

    Or I guess their make_method pathway.

  9. behrica commented on Sep 29, 2022

    @behrica
    behrica
    on Sep 29, 2022
    ContributorAuthor

    It does not happen with normal Clojure / JVM exceptions, that why I am wondering.

  10. cnuernber commented on Sep 29, 2022

    @cnuernber
    cnuernber
    on Sep 29, 2022
    Collaborator

    Hmm. In that case something needs to check the python exception state and rethrow.

  11. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    Using py/with-gil behaves "better" (and different depending on "manual gil or not")....

  12. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    So this code:

    (ns train
  (:require [libpython-clj2.python :refer [py.- py.] :as py]))


(py/with-gil
  (py/import-module "not existing"))

  13. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    called like this:

    export _JAVA_OPTIONS="-Dlibpython_clj.manual_gil=true";python -c 'from clojurebridge import cljbridge;cljbridge.load_clojure_file(clj_file="crash2.clj",mvn_local_repo="/home/carsten/.m2/repository")'

    gives

    ARNING: Please consider reporting this to the maintainers of tech.v3.datatype.UnsafeUtil
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007f92b2d87d7a, pid=38488, tid=38488
#
# JRE version: OpenJDK Runtime Environment (11.0.16.1+1) (build 11.0.16.1+1)
# Java VM: OpenJDK 64-Bit Server VM (11.0.16.1+1, mixed mode, tiered, compressed oops, g1 gc, linux-amd64)
# Problematic frame:
# C  [libpython3.10.so.1.0+0x187d7a]  PyImport_Import+0x3a
#
# Core dump will be written. Default location: Core dumps may be processed with "/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h" (or dumping to /home/carsten/Dropbox/sources/libpython-clj/core.38488)
#
# An error report file with more information is saved as:
# /home/carsten/Dropbox/sources/libpython-clj/hs_err_pid38488.log

  14. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    and called like this

    export _JAVA_OPTIONS="-Dlibpython_clj.manual_gil=false";python -c 'from clojurebridge import cljbridge;cljbridge.load_clojure_file(clj_file="crash2.clj",mvn_local_repo="/home/carsten/.m2/repository")'

    gives an Java exception (which I could probably catch):

    ARNING: All illegal access operations will be denied in a future release
Exception in thread "Thread-0" Syntax error macroexpanding at (/home/carsten/Dropbox/sources/libpython-clj/crash2.clj:5:1).
	at clojure.lang.Compiler.load(Compiler.java:7665)
	at clojure.lang.Compiler.loadFile(Compiler.java:7591)
	at clojure.lang.RT$3.invoke(RT.java:327)
	at clojure.lang.Var.invoke(Var.java:384)
Caused by: java.lang.Exception: ModuleNotFoundError: No module named 'not existing'

	at libpython_clj2.python.ffi$check_error_throw.invokeStatic(ffi.clj:708)
	at libpython_clj2.python.ffi$check_error_throw.invoke(ffi.clj:706)
	at libpython_clj2.python$import_module.invokeStatic(python.clj:165)
	at libpython_clj2.python$import_module.invoke(python.clj:158)
	at train$eval15837.invokeStatic(crash2.clj:6)
	at train$eval15837.invoke(crash2.clj:5)
	at clojure.lang.Compiler.eval(Compiler.java:7194)
	at clojure.lang.Compiler.load(Compiler.java:7653)
	... 3 more
Sep 30, 2022 10:30:39 AM clojure.tools.logging$eval3239$fn__3242 invoke
INFO: Reference thread starting
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/home/carsten/.local/lib/python3.10/site-packages/clojurebridge/cljbridge.py", line 187, in load_clojure_file
    resolve_call_fn("clojure.core/load-file",
  File "/home/carsten/.local/lib/python3.10/site-packages/clojurebridge/cljbridge.py", line 73, in resolve_call_fn
    return resolve_fn(namespaced_fn_name)(*args)
  File "/home/carsten/.local/lib/python3.10/site-packages/clojurebridge/cljbridge.py", line 50, in __call__
    return invoker(*args)
  File "/home/carsten/.local/lib/python3.10/site-packages/javabridge/jutil.py", line 961, in method
    result = call(self.o, name, sig, *args)
  File "/home/carsten/.local/lib/python3.10/site-packages/javabridge/jutil.py", line 892, in call
    result = fn(*nice_args)
  File "/home/carsten/.local/lib/python3.10/site-packages/javabridge/jutil.py", line 859, in fn
    raise JavaException(x)
javabridge.jutil.JavaException: Syntax error macroexpanding at (/home/carsten/Dropbox/sources/libpython-clj/crash2.clj:5:1).

    We can probably agree, that this is the expected behavior.

    A JVM exception and neither "jvm crash" nor "jvm hanging".

  15. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    And we have the correct behaviour in the REPL, in "Non-embedded"

  16. 1 remaining item

  17. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    It is documented here:
    https://clj-python.github.io/libpython-clj/embedded.html

    chapter: Loading and running a Clojure file in embedded mode

  18. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    The new entry point is here:
    https://github.com/behrica/clojurebridge/blob/2c3c6e6c6d3d74f61aa2d68d7bf1c770d76b09cc/src/clojurebridge/cljbridge.py#L173

    I think I do the "same" as the other entry point:
    https://github.com/behrica/clojurebridge/blob/2c3c6e6c6d3d74f61aa2d68d7bf1c770d76b09cc/src/clojurebridge/cljbridge.py#L142

  19. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    To make it more confusing, there is an other pathway I made as well, which loads a fixed "user.clj" file.

    This prints as well teh exception.....

    python -c 'from clojurebridge import cljbridge;cljbridge.init_jvm(load_user_clj=True,mvn_local_repo="/home/carsten/.m2/repository")'

    (I propose to later remove this load_user_clj pathway, as it is superseded by the load_clojure_file)

    So lets ignore this for the moment,

    I created: behrica/clojurebridge#5

  20. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    Let's concentrated on the "hanging" one, which is worst from a user experience point of view:

    crash.clj

    (ns train
  (:require [libpython-clj2.python :refer [py.- py.] :as py]
            [libpython-clj2.python.ffi :as ffi]))
            ;; [libpython-clj2.require :refer [require-python]]
            ;; [libpython-clj2.python.gc]
(println "-------- manual-gil: " ffi/manual-gil)

(def locked (ffi/lock-gil))
(println :gil-locked)

(println :before-crash)
(py/import-module "not existing")  ;; whatever error on python side, like loading an non existing library
(println "crash finished")

    run as

    export _JAVA_OPTIONS="-Dlibpython_clj.manual_gil=false";python -c 'from clojurebridge import cljbridge;cljbridge.load_clojure_file(clj_file="crash.clj",mvn_local_repo="/home/carsten/.m2/repository")'

    results in
    hanging for ever

    expected behaviour
    A nice JVM exception:

    Exception in thread "Thread-0" Syntax error macroexpanding at (/home/carsten/Dropbox/sources/libpython-clj/crash.clj:5:1).
	at clojure.lang.Compiler.load(Compiler.java:7665)
	at clojure.lang.Compiler.loadFile(Compiler.java:7591)
	at clojure.lang.RT$3.invoke(RT.java:327)
	at clojure.lang.Var.invoke(Var.java:384)
Caused by: java.lang.Exception: ModuleNotFoundError: No module named 'not existing'

  21. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    (same hanning happens without calling "lock/gil")

    and independent of the "manual_gil") setting, so we get an even easier hanging szenario:

  22. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    You might ask, why do I play with "manul_gil" and GIL locking.
    Because this makes python library simpletransformers work more reliable (proven by repeated executions and counting training sucecsses)

    But by doing so, I experience now the issue we discuss. If I get an python exception in my code with "manuel GIL handling", it hangs.

    As a "workaround" I now run it without manual GIL (to see if working on little data) and then switch to "with manual GIL" for train on full data, which is annoying to do.

    Especially because the instability of simpletransformers might result in "hanging" as well (or JVM crash)

  23. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    Even simpler code t reproduce:

    Any exception thronw by pythonresult in "hanging"

    (ns train
  (:require [libpython-clj2.python :refer [py.- py.] :as py]
            [libpython-clj2.python.ffi :as ffi]))


(def gil  (ffi/lock-gil))
(py/run-simple-string "invalid syntax !!!")
(ffi/unlock-gil gil)

    clled like this:

    export _JAVA_OPTIONS="-Dlibpython_clj.manual_gil=true"
python -c 'from clojurebridge import cljbridge;cljbridge.load_clojure_file(clj_file="crash.clj",mvn_local_repo="/home/carsten/.m2/repository")'

  24. cnuernber commented on Sep 30, 2022

    @cnuernber
    cnuernber
    on Sep 30, 2022
    Collaborator

    Well, I stand corrected :-). That definitely appears to be a bug in libpython-clj.

    Perhaps the unlock-gil code needs check-error-throw. Hmm - that needs to happen nearly after every python call - it was handled by with-gil and it should still be happening.

  25. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    I found a way to at least print the error, but it still hang

    diff --git a/src/libpython_clj2/python/ffi.clj b/src/libpython_clj2/python/ffi.clj
index 773d1f9..ec46e55 100644
--- a/src/libpython_clj2/python/ffi.clj
+++ b/src/libpython_clj2/python/ffi.clj
@@ -706,7 +706,8 @@ Each call must be matched with PyGILState_Release"}
 (defn check-error-throw
   []
   (when-let [error-str (check-error-str)]
-    (throw (Exception. ^String error-str))))
+    (do (println :error error-str)
+        (throw (Exception. ^String error-str)))))

  26. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    It gets as well solved by unlocking the gil in a finally

    (try
  (py/run-simple-string "1/0")
  (finally
    (ffi/unlock-gil gil)))

    I noticed already before, that in embedded mode and loading a clj file,
    the JVM does not terminate without the unlock

    So the "hanging" we see is maybe the following:

    The exception:

    1. is thrown
    2. not printed for whatever reason
    3. gil/unlock is not called
    4. code finishes
      5, JVM hangs

  27. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    so maybe it is simpler to find out and fix that in the following the VM does not terminate:

    (ns train
  (:require [libpython-clj2.python :refer [py.- py.] :as py]
            [libpython-clj2.python.ffi :as ffi]))


(def gil  (ffi/lock-gil))

(py/run-simple-string "print('ok')")

  28. behrica commented on Sep 30, 2022

    @behrica
    behrica
    on Sep 30, 2022
    ContributorAuthor

    I saw that in the hanging state some thread seems to wait forever:

    Name: tech.resource.gc ref thread
State: TIMED_WAITING on java.lang.ref.ReferenceQueue$Lock@28f1bb74
Total blocked: 1  Total waited: 87,568

Stack trace: 
java.base@11.0.16.1/java.lang.Object.wait(Native Method)
java.base@11.0.16.1/java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:155)
tech.v3.resource.gc$watch_reference_queue$fn__10795.invoke(gc.clj:27)
tech.v3.resource.gc$watch_reference_queue.invokeStatic(gc.clj:23)
tech.v3.resource.gc$watch_reference_queue.invoke(gc.clj:21)
tech.v3.resource.gc$start_reference_thread$fn__10807.invoke(gc.clj:47)
app//clojure.lang.AFn.run(AFn.java:22)
java.base@11.0.16.1/java.lang.Thread.run(Thread.java:829)

    not sure, if relevant

  29. cnuernber commented on Sep 30, 2022

    @cnuernber
    cnuernber
    on Sep 30, 2022
    Collaborator

    The java api has a try-with-resources pattern -

    (with-open [glock (java_api/GILLocker)]
  ...)

    That will automatically do the try-finally. Anything auto-closeable will be closed in a with-open macro.

  30. cnuernber commented on Oct 2, 2022

    @cnuernber
    cnuernber
    on Oct 2, 2022
    Collaborator

    There is a new API in latest (2.020) - with-manual-gil that will automatically lock/unlock the gil.

    user> ffi/manual-gil
true
user> (py/with-manual-gil
        (py/run-simple-string "!! syntax error"))
Execution error at libpython-clj2.python.ffi/check-error-throw (ffi.clj:708).
  File "<string>", line 1
    !! syntax error
    ^
SyntaxError: invalid syntax
user>

    Outputs:

  31. cnuernber
    closed this as completedon Oct 2, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions