search

softwareCobbler / luceedebug

line debugger for lucee
GNU Lesser General Public License v2.1
44 stars 15 forks source link

java.lang.NullPointerException on Lucee Restart #41

Open chapmandu opened 1 year ago

chapmandu commented 1 year ago

When restarting Lucee via the admin UI, the NullPointerException below is thrown. The service starts as expected and Luceedebug is fully operational until restarting.

If I remove these 2 jvm args, the service will restart as expected,

"-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=localhost:9999",
      "-javaagent:/app/lib/luceedebug.jar=jdwpHost=localhost,jdwpPort=9999,debugHost=0.0.0.0,debugPort=10000,jarPath=/app/lib/luceedebug.jar"

Lucee 5.3.10.97 Lucee Debug @ https://github.com/softwareCobbler/luceedebug/commit/084fa57ad8bfa5e8ec230a1658e656ae14024c63 Docker Commandbox Ubuntu Linux

[INFO] 2023-05-26T05:29:33Z - Starting server using generated script: /usr/bin/startup.sh
Listening for transport dt_socket at address: 9999
[luceedebug] fs is case sensitive: true
[luceedebug] agent premain complete
[INFO ] runwar.server: ******************************************************************************
[INFO ] runwar.server: Starting RunWAR 4.8.3
[INFO ] runwar.server: Binding HTTP on 0.0.0.0:80
[INFO ] runwar.server: Enabling HTTP/2
[INFO ] runwar.server: Binding SSL on 0.0.0.0:443
[INFO ] runwar.server: Servlet Context: /
[INFO ] runwar.server: Log Directory: /usr/lib/serverHome/logs
[INFO ] runwar.server: ******************************************************************************
[INFO ] runwar.config: Parsing '/usr/lib/serverHome/WEB-INF/web.xml'
[INFO ] runwar.server: Creating deployment [default] in /app
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender (file:/usr/lib/serverHome/WEB-INF/lib/lucee.jar) to method java.net.URLClassLoader.addURL(java.net.URL)
WARNING: Please consider reporting this to the maintainers of org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender
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
[INFO ] runwar.context: [luceedebug] Loaded luceedebug.coreinject.DebugManager@2b10ace9 with ClassLoader 'lucee.core [49]'
[INFO ] runwar.context: [luceedebug] attempting jdwp self connect to jdwp on localhost:9999...
[INFO ] runwar.context: [luceedebug] jdwp self connect OK
[INFO ] runwar.server: ******************************************************************************
[INFO ] runwar.server: *** starting 'stop' listener thread - Host: 0.0.0.0 - Socket: 34723
[INFO ] runwar.server: ******************************************************************************
[INFO ] runwar.server: Server is up - http-port:80 https-port:443 stop-port:34723 PID:1 version 4.8.3
[ERROR] runwar.context: java.lang.NullPointerException
[ERROR] runwar.context:     at luceedebug.LuceeTransformer.transform(LuceeTransformer.java:96)
[ERROR] runwar.context:     at java.instrument/java.lang.instrument.ClassFileTransformer.transform(ClassFileTransformer.java:246)
[ERROR] runwar.context:     at java.instrument/sun.instrument.TransformerManager.transform(TransformerManager.java:188)
[ERROR] runwar.context:     at java.instrument/sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:563)
[ERROR] runwar.context:     at java.base/java.lang.ClassLoader.defineClass1(Native Method)
[ERROR] runwar.context:     at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017)
[ERROR] runwar.context:     at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.defineClass(BundleWiringImpl.java:2312)
[ERROR] runwar.context:     at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.defineClassParallel(BundleWiringImpl.java:2130)
[ERROR] runwar.context:     at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.findClass(BundleWiringImpl.java:2064)
[ERROR] runwar.context:     at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1533)
[ERROR] runwar.context:     at org.apache.felix.framework.BundleWiringImpl.access$300(BundleWiringImpl.java:78)
[ERROR] runwar.context:     at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1950)
[ERROR] runwar.context:     at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
[ERROR] runwar.context:     at java.base/java.lang.Class.getDeclaredMethods0(Native Method)
[ERROR] runwar.context:     at java.base/java.lang.Class.privateGetDeclaredMethods(Class.java:3166)
[ERROR] runwar.context:     at java.base/java.lang.Class.getMethodsRecursive(Class.java:3307)
[ERROR] runwar.context:     at java.base/java.lang.Class.getMethod0(Class.java:3293)
[ERROR] runwar.context:     at java.base/java.lang.Class.getMethod(Class.java:2106)
[ERROR] runwar.context:     at lucee.loader.engine.CFMLEngineFactory.getEngine(CFMLEngineFactory.java:1468)
[ERROR] runwar.context:     at lucee.loader.engine.CFMLEngineFactory.initEngine(CFMLEngineFactory.java:384)
[ERROR] runwar.context:     at lucee.loader.engine.CFMLEngineFactory._restart(CFMLEngineFactory.java:617)
[ERROR] runwar.context:     at lucee.loader.engine.CFMLEngineFactory.restart(CFMLEngineFactory.java:596)
[ERROR] runwar.context:     at lucee.runtime.config.XMLConfigAdmin.restart(XMLConfigAdmin.java:3947)
[ERROR] runwar.context:     at lucee.runtime.tag.Admin.doRestart(Admin.java:947)
[ERROR] runwar.context:     at lucee.runtime.tag.Admin._doStartTag(Admin.java:876)
[ERROR] runwar.context:     at lucee.runtime.tag.Admin.doStartTag(Admin.java:364)
[ERROR] runwar.context:     at restart_cfm$cf.__luceedebug__call(/admin/restart.cfm:6)
[ERROR] runwar.context:     at restart_cfm$cf.call(/admin/restart.cfm)
[ERROR] runwar.context:     at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:1025)
[ERROR] runwar.context:     at lucee.runtime.PageContextImpl._doInclude(PageContextImpl.java:948)
[ERROR] runwar.context:     at lucee.runtime.listener.ModernAppListener._onRequest(ModernAppListener.java:219)
[ERROR] runwar.context:     at lucee.runtime.listener.MixedAppListener.onRequest(MixedAppListener.java:44)
[ERROR] runwar.context:     at lucee.runtime.PageContextImpl.execute(PageContextImpl.java:2493)
[ERROR] runwar.context:     at lucee.runtime.PageContextImpl._execute(PageContextImpl.java:2478)
[ERROR] runwar.context:     at lucee.runtime.PageContextImpl.executeCFML(PageContextImpl.java:2449)
[ERROR] runwar.context:     at lucee.runtime.engine.Request.exe(Request.java:45)
[ERROR] runwar.context:     at lucee.runtime.engine.CFMLEngineImpl._service(CFMLEngineImpl.java:1216)
[ERROR] runwar.context:     at lucee.runtime.engine.CFMLEngineImpl.serviceCFML(CFMLEngineImpl.java:1162)
[ERROR] runwar.context:     at lucee.loader.engine.CFMLEngineWrapper.serviceCFML(CFMLEngineWrapper.java:97)
[ERROR] runwar.context:     at lucee.loader.servlet.CFMLServlet.service(CFMLServlet.java:51)
[ERROR] runwar.context:     at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
[ERROR] runwar.context:     at org.cfmlprojects.regexpathinfofilter.RegexPathInfoFilter.doFilter(RegexPathInfoFilter.java:47)
[ERROR] runwar.context:     at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
[ERROR] runwar.context:     at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176)
[ERROR] runwar.context:     at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
[ERROR] runwar.context:     at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
[ERROR] runwar.context:     at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:405)
[ERROR] runwar.context:     at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
[ERROR] runwar.context:     at runwar.undertow.SSLClientCertHeaderHandler.handleRequest(SSLClientCertHeaderHandler.java:144)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
[ERROR] runwar.context:     at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[ERROR] runwar.context:     at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
[ERROR] runwar.context:     at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
[ERROR] runwar.context:     at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
[ERROR] runwar.context:     at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
[ERROR] runwar.context:     at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:275)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:79)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:134)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:131)
[ERROR] runwar.context:     at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
[ERROR] runwar.context:     at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
[ERROR] runwar.context:     at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:255)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:79)
[ERROR] runwar.context:     at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:100)
[ERROR] runwar.context:     at io.undertow.server.Connectors.executeRootHandler(Connectors.java:393)
[ERROR] runwar.context:     at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:852)
[ERROR] runwar.context:     at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
[ERROR] runwar.context:     at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2019)
[ERROR] runwar.context:     at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1558)
[ERROR] runwar.context:     at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1449)
[ERROR] runwar.context:     at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
[ERROR] runwar.context:     at java.base/java.lang.Thread.run(Thread.java:829)

image

softwareCobbler commented 1 year ago

We null out a ref under the assumption we will never need it again; but then need it again, upon this reset action. Thanks for the report, will investigate.

Symbianx commented 9 months ago

We've started having this issue as well as soon as the container starts. Attaching the debugger as soon as jdwp self connect OK is logged is a workaround, but it's not a great experience.

softwareCobbler commented 9 months ago

We have this looking like it's fixed after some local testing, on branch handle-lucee-restart. Let us know if you encounter any issues, or if it appears fixed on your end, too.

Symbianx commented 5 months ago

Hey @softwareCobbler sorry it took me so long to give this a try but after trying your branch, the application fails to start with a different error.

The app was compiled from your branch on a Mac with ./gradlew shadowjar

Here's the error:

[ERROR] runwar.context: java.lang.reflect.InvocationTargetException
[ERROR] runwar.context: at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[ERROR] runwar.context: at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
[ERROR] runwar.context: at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[ERROR] runwar.context: at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
[ERROR] runwar.context: at luceedebug.LuceeTransformer.transform(LuceeTransformer.java:109)
[ERROR] runwar.context: at java.instrument/java.lang.instrument.ClassFileTransformer.transform(ClassFileTransformer.java:246)
[ERROR] runwar.context: at java.instrument/sun.instrument.TransformerManager.transform(TransformerManager.java:188)
[ERROR] runwar.context: at java.instrument/sun.instrument.InstrumentationImpl.transform(InstrumentationImpl.java:563)
[ERROR] runwar.context: at java.base/java.lang.ClassLoader.defineClass1(Native Method)
[ERROR] runwar.context: at java.base/java.lang.ClassLoader.defineClass(ClassLoader.java:1017)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.defineClass(BundleWiringImpl.java:2344)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.defineClassParallel(BundleWiringImpl.java:2162)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.findClass(BundleWiringImpl.java:2096)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1565)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl.access$300(BundleWiringImpl.java:79)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1982)
[ERROR] runwar.context: at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
[ERROR] runwar.context: at java.base/java.lang.Class.getDeclaredMethods0(Native Method)
[ERROR] runwar.context: at java.base/java.lang.Class.privateGetDeclaredMethods(Class.java:3166)
[ERROR] runwar.context: at java.base/java.lang.Class.getMethodsRecursive(Class.java:3307)
[ERROR] runwar.context: at java.base/java.lang.Class.getMethod0(Class.java:3293)
[ERROR] runwar.context: at java.base/java.lang.Class.getMethod(Class.java:2106)
[ERROR] runwar.context: at lucee.loader.engine.CFMLEngineFactory.getEngine(CFMLEngineFactory.java:1448)
[ERROR] runwar.context: at lucee.loader.engine.CFMLEngineFactory._getCore(CFMLEngineFactory.java:565)
[ERROR] runwar.context: at lucee.loader.engine.CFMLEngineFactory.initEngine(CFMLEngineFactory.java:370)
[ERROR] runwar.context: at lucee.loader.engine.CFMLEngineFactory.initEngineIfNecessary(CFMLEngineFactory.java:262)
[ERROR] runwar.context: at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:168)
[ERROR] runwar.context: at lucee.loader.engine.CFMLEngineFactory.getInstance(CFMLEngineFactory.java:202)
[ERROR] runwar.context: at lucee.loader.servlet.LuceeServlet.init(LuceeServlet.java:42)
[ERROR] runwar.context: at io.undertow.servlet.core.LifecyleInterceptorInvocation.proceed(LifecyleInterceptorInvocation.java:117)
[ERROR] runwar.context: at io.undertow.servlet.core.ManagedServlet$DefaultInstanceStrategy.start(ManagedServlet.java:305)
[ERROR] runwar.context: at io.undertow.servlet.core.ManagedServlet.createServlet(ManagedServlet.java:145)
[ERROR] runwar.context: at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:588)
[ERROR] runwar.context: at io.undertow.servlet.core.DeploymentManagerImpl$2.call(DeploymentManagerImpl.java:559)
[ERROR] runwar.context: at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:42)
[ERROR] runwar.context: at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
[ERROR] runwar.context: at io.undertow.servlet.core.DeploymentManagerImpl.start(DeploymentManagerImpl.java:601)
[ERROR] runwar.context: at runwar.Server.startServer(Server.java:553)
[ERROR] runwar.context: at runwar.Start.main(Start.java:123)
[ERROR] runwar.context: Caused by: java.lang.NoClassDefFoundError: luceedebug_shadow/com/google/common/collect/MapMaker
[ERROR] runwar.context: at luceedebug.coreinject.DebugManager.<init>(DebugManager.java:484)
[ERROR] runwar.context: ... 39 more
[ERROR] runwar.context: Caused by: java.lang.ClassNotFoundException: luceedebug_shadow.com.google.common.collect.MapMaker not found by lucee.core [48]
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl.findClassOrResourceByDelegation(BundleWiringImpl.java:1597)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl.access$300(BundleWiringImpl.java:79)
[ERROR] runwar.context: at org.apache.felix.framework.BundleWiringImpl$BundleClassLoader.loadClass(BundleWiringImpl.java:1982)
[ERROR] runwar.context: at java.base/java.lang.ClassLoader.loadClass(ClassLoader.java:522)
[ERROR] runwar.context: ... 40 more
[INFO ] runwar.server: ******************************************************************************
[INFO ] runwar.server: *** stopping server 'www' (socket 45975)
[INFO ] runwar.server: ******************************************************************************