Issue2844

classification
Title: PyServlet not working anymore
Type: crash Severity: urgent
Components: Core Versions: Jython 2.7.2
Milestone: Jython 2.7.2
process
Status: pending Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: gbach, jeff.allen
Priority: high Keywords:

Created on 2019-12-11.12:32:40 by gbach, last changed 2019-12-24.15:05:11 by jeff.allen.

Messages
msg12820 (view) Author: Gunter (gbach) Date: 2019-12-11.12:32:40
When updating a working webapplication from jython 2.7.1 to jython 2.7.2b2 (because of issue2487) it does not start anymore without any error or log-entry.
The container (tomcat 7) only tells me that the "Deployment of web application directory ... has finished" but the servlet is not setup.

I can reproduce this behaviour with the help of this guide: https://seanmcgrath.blogspot.com/JythonWebAppTutorialPart1.html.

I get:

HTTP Status 500 – Internal Server Error

Type Exception Report

Message Servlet.init() for servlet PyServlet threw exception

Description The server encountered an unexpected condition that prevented it from fulfilling the request.

Exception

javax.servlet.ServletException: Servlet.init() for servlet PyServlet threw exception
	org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:444)
	org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
	org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:1025)
	org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
	org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1137)
	org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
	org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:317)
	java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	java.lang.Thread.run(Thread.java:748)

Root Cause

java.lang.NoClassDefFoundError: Could not initialize class org.python.core.PySystemState
	org.python.util.PyServlet.createInterpreter(PyServlet.java:123)
	org.python.util.PyServlet.reset(PyServlet.java:170)
	org.python.util.PyServlet.init(PyServlet.java:90)
	javax.servlet.GenericServlet.init(GenericServlet.java:158)
	org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:444)
	org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:104)
	org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:1025)
	org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
	org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1137)
	org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
	org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:317)
	java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	java.lang.Thread.run(Thread.java:748)

Note The full stack trace of the root cause is available in the server logs.
Apache Tomcat/7.0.96


----
Java is jdk-8u231-linux-x64
Tomcat is apache-tomcat-7.0.96
Jython is jython-installer-2.7.2b2
msg12844 (view) Author: Jeff Allen (jeff.allen) Date: 2019-12-15.18:06:20
I confirm I can reproduce this and I think we ought to address it for 2.7.2.

"Could not initialize class org.python.core.PySystemState" is interesting: it must be able to find it, but clearly something goes wrong in the initialisation of that class. I wonder what.

I think a bit of logging from Jython during start-up would be a help, here and in future. Now we use JUL, I assume it would come out in server logs in a natural (and configurable) way.
msg12846 (view) Author: Jeff Allen (jeff.allen) Date: 2019-12-15.21:38:27
With just jython.jar, copied from an installation, it produces the effect reported. If I turn on logging for the jythondemo application (via WEB-INF/classes/logging.properties), the reasons are apparent:


Dec 15, 2019 9:19:54 PM org.apache.catalina.core.StandardContext loadOnStartup
SEVERE: Servlet [PyServletTest] in web application [/jythondemo] threw load() exception
ImportError: Cannot import site module and its dependencies: No module named site
Determine if the following attributes are correct:
  * sys.path: [D:\web\base\webapps\jythondemo\WEB-INF\lib\Lib, __classpath__, __pyclasspath__/]
    This attribute might be including the wrong directories, such as from CPython
  * sys.prefix: D:\web\base\webapps\jythondemo\WEB-INF\lib
    This attribute is set by the system property python.home, although it can
    be often automatically determined by the location of the Jython jar file

You can use the -S option or python.import.site=false to not import the site module


(I am using the (potentially) multi-instance configuration with CATALINA_BASE=D:\web\base.) It is only necessary to provide the standard library at WEB-INF\lib\Lib and it all seems to work ok. I don't think any of this is different in 2.7.2 from 2.7.1, so I'm puzzled you experience this as a new failure, all other things being equal.

I find I can also get the tutorial example working if I use the jython-standalone JAR (in the WEB-INF/lib of my application). (That JAR includes the the Lib directory.)

I currently lean towards marking this issue invalid. (However, I learned some new things, so that's ok.)
msg12856 (view) Author: Gunter (gbach) Date: 2019-12-18.15:21:59
What I lerned is:
jython2.7.2b2 seems to be less fault tolerant to lousy configurations.
PrePy.java needs the org.python.level defined in logging.properties or else it fails with an NPE.
I did not manage to get the live-application working with 2.7.2b2 but this issue seems to have a related background. 
If this is now a bug or works-as-designed is a political question...
msg12858 (view) Author: Jeff Allen (jeff.allen) Date: 2019-12-18.21:13:57
"PrePy.java needs the org.python.level defined in logging.properties or else it fails with an NPE."

Yes, I found the same while trying to turn bits of logging off and on thanks to your raising this issue. I have already committed a fix locally. Actually, you have diagnosed it more precisely than I did. I made it report Level.INFO in the parent is null without an explicit level being found.

The intention in introducing the "org.python" logging was to blend what Jython has to say with the logging infrastructure of applications like yours. If I've mucked it up, that's not by design. If you trace why you can't get the application up to more bugs, do let us know.

I infer that you got the tutorial working as I did.
msg12862 (view) Author: Gunter (gbach) Date: 2019-12-20.09:14:18
I managed to get my application booting with 2.7.2b2. Now I am getting an error regarding some encoding-issue... I will check if this change in behaviour from 2.7.1 to 2.7.2b2 is a step torwards python-compatibility or the opposite. If I think its an yet unreported bug I will create another issue here.
msg12884 (view) Author: Jeff Allen (jeff.allen) Date: 2019-12-24.15:05:11
Minor changes that stem from my investigation of this issue (including adjustments to logging) are at: https://hg.python.org/jython/rev/84ad2ab25bca

The encoding problem will be a separate issue. We got more consistent through 2.7.0 to 2.7.2 in handling encodings, but it comes out as "stricter" in places.
History
Date User Action Args
2019-12-24 15:05:11jeff.allensetstatus: open -> pending
resolution: accepted -> fixed
messages: + msg12884
2019-12-20 09:14:18gbachsetmessages: + msg12862
2019-12-18 21:13:57jeff.allensetmessages: + msg12858
2019-12-18 15:22:00gbachsetmessages: + msg12856
2019-12-15 21:38:27jeff.allensetmessages: + msg12846
2019-12-15 18:06:20jeff.allensetpriority: high
resolution: accepted
messages: + msg12844
nosy: + jeff.allen
milestone: Jython 2.7.2
2019-12-11 12:32:40gbachcreate