Issue2844

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

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.

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.)

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...

"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.

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.

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.