Convert Python stack trace to Java stack trace

[drj11]

If the Python code raises an Exception then this GATE plugin handles this by noting that it couldn't read JSON from the Python process and closing the pipeline.

In some sense this works, in that processing is halted, but it's not very clean and the plugin couldn't be more intelligent about catching the Exception (on the Python side) and reporting it via a particular JSON message.

Here's an example from a (accidentally misconfigured) rumourVeracity Python code:

Using Theano backend.
Traceback (most recent call last):
  File "/home/ac1xdrj/prj/models/rumourVeracity/veracity_gate.py", line 4, in <module>
    from innerAttentionModel import InnerAttentionModel
  File "/home/ac1xdrj/prj/models/rumourVeracity/innerAttentionModel.py", line 5, in <module>
    from keras import backend as K
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/__init__.py", line 3, in <module>
    from . import utils
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/utils/__init__.py", line 6, in <module>
    from . import conv_utils
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/utils/conv_utils.py", line 9, in <module>
    from .. import backend as K
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/backend/__init__.py", line 86, in <module>
    from .theano_backend import *
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/backend/theano_backend.py", line 7, in <module>
    import theano
ImportError: No module named theano
Unable to read JSON from python process, closing pipeline
com.fasterxml.jackson.databind.JsonMappingException: No content to map due to end-of-input
 at [Source: java.io.BufferedReader@69946c29; line: 1, column: 1]
	at com.fasterxml.jackson.databind.JsonMappingException.from(JsonMappingException.java:164)
	at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3036)
	at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:2978)
	at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2128)
	at gate.python.PythonPR.execute(PythonPR.java:158)
	at gate.util.Benchmark.executeWithBenchmarking(Benchmark.java:291)
	at gate.creole.SerialController.runComponent(SerialController.java:225)
	at gate.creole.SerialController.executeImpl(SerialController.java:157)
	at gate.creole.AbstractController.execute(AbstractController.java:78)
	at gate.util.Benchmark.executeWithBenchmarking(Benchmark.java:291)
	at gate.gui.SerialControllerEditor$RunAction$1.run(SerialControllerEditor.java:1759)
	at java.lang.Thread.run(Thread.java:748)
gate.creole.ExecutionException: Unable to read JSON from python process - perhaps process printed to stdout? (use stderr instead)
	at gate.python.PythonPR.execute(PythonPR.java:165)
	at gate.util.Benchmark.executeWithBenchmarking(Benchmark.java:291)
	at gate.creole.SerialController.runComponent(SerialController.java:225)
	at gate.creole.SerialController.executeImpl(SerialController.java:157)
	at gate.creole.AbstractController.execute(AbstractController.java:78)
	at gate.util.Benchmark.executeWithBenchmarking(Benchmark.java:291)
	at gate.gui.SerialControllerEditor$RunAction$1.run(SerialControllerEditor.java:1759)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.fasterxml.jackson.databind.JsonMappingException: No content to map due to end-of-input
 at [Source: java.io.BufferedReader@69946c29; line: 1, column: 1]
	at com.fasterxml.jackson.databind.JsonMappingException.from(JsonMappingException.java:164)
	at com.fasterxml.jackson.databind.ObjectMapper._initForReading(ObjectMapper.java:3036)
	at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:2978)
	at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:2128)
	at gate.python.PythonPR.execute(PythonPR.java:158)
	... 7 more
Using Theano backend.
Traceback (most recent call last):
  File "/home/ac1xdrj/prj/models/rumourVeracity/veracity_gate.py", line 4, in <module>
    from innerAttentionModel import InnerAttentionModel
  File "/home/ac1xdrj/prj/models/rumourVeracity/innerAttentionModel.py", line 5, in <module>
    from keras import backend as K
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/__init__.py", line 3, in <module>
    from . import utils
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/utils/__init__.py", line 6, in <module>
    from . import conv_utils
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/utils/conv_utils.py", line 9, in <module>
    from .. import backend as K
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/backend/__init__.py", line 86, in <module>
    from .theano_backend import *
  File "/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/backend/theano_backend.py", line 7, in <module>
    import theano
ImportError: No module named theano

[drj11]

To be fair the current behaviour is acceptable, no-one is harmed and all the tracebacks and output are there (twice, in some cases!), it's more of a "this would be neater if..."

[ianroberts]

If the tracebacks can be captured nicely on the Python side then we can even fake the python traceback into the Java one (see Throwable.setStackTrace) so it comes out as e.g.

gate.creole.ExecutionException: Exception in Python code: ImportError: No module named theano
        at python(/home/ac1xdrj/prj/models/rumourVeracity/venv/local/lib/python2.7/site-packages/keras/backend/theano_backend.py:7)
        <a load more stack frames>
        at python(/home/ac1xdrj/prj/models/rumourVeracity/innerAttentionModel.py:5)
        at python(/home/ac1xdrj/prj/models/rumourVeracity/veracity_gate.py:4)
        at gate.python.PythonPR.execute(PythonPR.java:165)
	at gate.util.Benchmark.executeWithBenchmarking(Benchmark.java:291)

[johann-petrak]

This should work properly in the 2.0-SNAPSHOT version, but faking the python traceback into the Java one is not implemented yet.

[johann-petrak]

@ianroberts do you have code to convert a python stackframe to a java traceback as in the example you give?

[johann-petrak]

I think I am happy with just getting the original python stacktrace as message of a single Exception on the Java side for now.
If somebody feels strongly about the conversion into a Java stack trace, please open another issue to discuss the details there.

[greenwoodma]

I agree that it would be nice to do this as a stack trace so that those of us who are more Java experts than Python can see something that at a glance we can understand. Although I also agree that it's not hugely important.

There is an example of setting the stack trace when looking at none Java files as part of the Jape code. Specifically see here https://github.com/GateNLP/gateplugin-ANNIE/blob/fea2e875a5aedb1b8f602f65d9902a9d5078c6ae/src/main/java/gate/jape/SourceInfo.java#L92

[greenwoodma]

Could we repoen the issue, but mark as an enhancement so that if someone has the time they could come back and improve this later? If the issue is closed it just disappears from view and will get forgotten.

[johann-petrak]

TBH I am not sure how much this would be helping: the conversion may make it harder to find the actual Python stacktrace among some big Java stacktrace because then both would look very similar. On the other hand a nicely formatted python stacktrace could be made to stand out.

I would still be interested if the example from @ianroberts above is the output of testing code or just manually written fake output? If we can make it look like that, maybe with "at PYTHON" screaming at us, it could be an option.

[ianroberts]

I would still be interested if the example from @ianroberts above is the output of testing code or just manually written fake output?

It's manually faked up but based on what is done by the JAPE SourceInfo that Mark linked to above.

[johann-petrak]

I have updated the way how Python exceptions get shown on the Java side. At the moment, the python process writes a traceback to stderr which should always get copied to the java side (as stdout like all other stderr from python).
In addition, the python process sends back the exception message and an info string which is the formatted traceback from python which gets then printed as part of the Java exception (this goes to the error logger, i.e. stderr in the GUI)
The reason why it could be useful to always copy the traceback from the python process output is that sending back the traceback or stack trace is something that involves the JSON communication where we could also have a problem. In such a case we would not get useful information on the java side.

Either way, getting the Python traceback that way is easily readable and has the advantage that it stands out from the Java stacktrace, so it is actually easier to figure out where to look for the Python error than it would be if the Python traceback looks exactly like the Java traceback. I am now even more in favour of not converting.
Any other reasons why the conversion would be an advantage?

[greenwoodma]

Well my original reason still stands; Java developers will be able to read the Java stacktrace much easier (at a glance really) to follow the flow into the python code than they will the Python traceback which may be something they have never seen before. I know I'm probably in the minority with my lack of python experience, but making life easier for Java developers in general can't be a bad thing.

At the end of the day it would be a nice feature to have (which is why I suggested leaving the issue open with an enhancement label) but not a blocker for release.

[johann-petrak]

I am pretty sure it does not stand. If somebody cannot read the original python stacktrace which is shown both on the standard output and whatever logger the exception is going to, then they probably do not want to use Python in the first place.
I cannot see any benefit of converting this, other than making it more obscure and less easy to read for people who expect a python stacktrace.

[ianroberts]

The one benefit I can see to massaging the python stack trace into the Java exception is for situations where the GATE code is embedded in something else and propagates exceptions out to the caller. If we want the caller to be able to do something intelligent with the stack trace like forward it on elsewhere or log it in a database then the trace has to be a stack trace in the Exception object rather than just some text that has been printed to System.out or sent to an slf4j logger.

[johann-petrak]

The Python stack trace is in the message of the exception, so it gets sent to wherever the exception gets send, a logger, a database or whatever. When I mentioned the logger above I was referring to the mechanism that logs exceptions on the Java side.

[greenwoodma]

Yes, but the python traceback is only in the message field of the Java stacktrace and depending on how far these things get nested, caught, and possibly re-thrown the messages aren't always shown, but the stack trace itself is always preserved and can be interrogated through the API.

As I said yesterday it's not a blocker but I'd still like to leave the issue open labelled as an enhancement so that when one of us has the time and enthusiasm we can improve the Java stack trace just to be ultra sure we get the root cause through. Given I've had no end of problems debugging stuff running in the old version of the plugin, anything that even remotely helps is worth it in my opinion.

[johann-petrak]

I would not have expected a situation so weird that the original exception text gets lost but the full stack trace is kept, but if you really feel strongly about this ...

The Python code already has the capability of sending the Python stacktrace back to Java as an array of tuples (filename, linenumber, functionname, linenumber) and we get the stacktrace as a List<List> so it should not be too hard to implement this.

Should this get implemented I guess we better remove the full stacktrace text from the exception message to avoid having it appear three times :)

[johann-petrak]

Given I've had no end of problems debugging stuff running in the old version of the plugin, anything that even remotely helps is worth it in my opinion.

I think it could be helpful if you could try things out and test running the new plugin with this and see how it works and how easy it is to figure out problems on the Python side.

See #29

[greenwoodma]

Yes, testing this is on my long to do list, it's unfortunately not as high up the list as I'd like

[johann-petrak]

No problem, I can live with the testing happening after v2.0, my tests with the GUI and GCP looked allright so far.