search

kitodo / kitodo-production

Kitodo.Production is a workflow management tool for mass digitization and is part of the Kitodo Digital Library Suite.
http://www.kitodo.org/software/kitodoproduction/
GNU General Public License v3.0
59 stars 65 forks source link

NullPointerException in de.sub.goobi.metadaten.Metadaten.getMyGroups #601

Closed stweil closed 7 years ago

stweil commented 7 years ago

Users report random failures (cannot be reproduced, but occur several times per day) in our production system (based on 1.11.2). The time of those failures correspond with Tomcat reports.

Extract from /var/log/tomcat7/localhost.2016-12-09.log:

Dez 09, 2016 12:08:36 PM org.apache.catalina.core.ApplicationDispatcher invoke
SCHWERWIEGEND: Servlet.service() for servlet jsp threw exception
java.lang.NullPointerException
        at de.sub.goobi.metadaten.Metadaten.getMyGroups(Metadaten.java:3125)
        at sun.reflect.GeneratedMethodAccessor994.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.apache.myfaces.el.PropertyResolverImpl.getProperty(PropertyResolverImpl.java:457)
        at org.apache.myfaces.el.PropertyResolverImpl.getValue(PropertyResolverImpl.java:85)
        at org.apache.myfaces.custom.security.SecurityContextPropertyResolver.getValue(SecurityContextPropertyResolver.java:101)
        at org.apache.myfaces.el.ELParserHelper$MyPropertySuffix.evaluate(ELParserHelper.java:535)
        at org.apache.commons.el.ComplexValue.evaluate(ComplexValue.java:145)
        at org.apache.commons.el.UnaryOperatorExpression.evaluate(UnaryOperatorExpression.java:156)
        at org.apache.myfaces.el.ValueBindingImpl.getValue(ValueBindingImpl.java:386)
        at javax.faces.component.UIComponentBase.isRendered(UIComponentBase.java:1078)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:408)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGroupRendererBase.encodeEnd(HtmlGroupRendererBase.java:78)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:419)
        at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
        at org.apache.myfaces.shared_impl.renderkit.html.HtmlGroupRendererBase.encodeEnd(HtmlGroupRendererBase.java:78)
        at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
        at javax.faces.webapp.UIComponentTag.encodeEnd(UIComponentTag.java:498)
        at javax.faces.webapp.UIComponentTag.doEndTag(UIComponentTag.java:366)
        at org.apache.myfaces.shared_impl.taglib.UIComponentBodyTagBase.doEndTag(UIComponentBodyTagBase.java:57)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_h_005fpanelGroup_005f2(Metadaten2rechts_jsp.java:2762)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_h_005fform_005f1(Metadaten2rechts_jsp.java:2656)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_htm_005ftd_005f4(Metadaten2rechts_jsp.java:2554)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_htm_005ftr_005f3(Metadaten2rechts_jsp.java:2516)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_htm_005ftable_005f2(Metadaten2rechts_jsp.java:2381)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_f_005fview_005f0(Metadaten2rechts_jsp.java:1105)
        at org.apache.jsp.pages.Metadaten2rechts_jsp._jspService(Metadaten2rechts_jsp.java:706)
        at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)
[...]

I could get a similar stack trace by simply loading http://MYHOST:8080/kitodo/pages/Metadaten2rechts.jsf in a web browser.

henning-gerhardt commented 7 years ago

I can reproduce this only if I opened this page without a valid user session.

The user(s) maybe open possible links inside metadata editor (pagination / structure data / metadata / file editor / ...) into new browser tabs or windows and using them to work with multiple browser tabs / browser windows.

User sessions are updated while using them into a browser. If a separated tab / window is not used regular then this user session is expiring and above mentioned error occur. This could even happen if a user is too long away and tried to working.

While working with multiple tabs / browser is current state of work the software was developed as multiple browser sessions was not known or not usable.

stweil commented 7 years ago

Then maybe Kitodo does not work as expected by users.

From a user point of view, I'd expect one session id which is assigned when I log on and which is used for all browser tabs / Windows. This session id may have a limited life time, but it should be refreshed by user actions, no matter in which window these actions occur.

Exceptions which are shown to the end user should always be considered as a programming bug, no matter whether they were caused by wrong input or by session timeouts. Invalid sessions should fall back to the login page.

matthias-ronge commented 7 years ago

JSF seems to be based on the assumption that getters never crash. It requires to call the getters prior to being able to process the incoming HTTP request, so maybe a session check is not reached ever. The getter in question is accessed in pages/incMeta/PersonenUndMetadaten.jsp line 125:

<h:panelGroup rendered="#{!empty Metadaten.myGroups}">

Correct behaviour should be to return an empty list in case of a null object in Metadaten.java line 3125:

List<MetadataGroup> records = myDocStruct.getAllMetadataGroups();
if (records == null) {
    return Collections.emptyList();
}

needs to be changed to

List<MetadataGroup> records;
if (myDocStruct == null || (records = myDocStruct.getAllMetadataGroups()) == null) {
    return Collections.emptyList();
}
henning-gerhardt commented 7 years ago

@stweil: Kitodo.Production is already using a session id but this session id is not updated on inactive tabs / browsers! If an inactive session id is re-used then the user gets already a login screen but with an exception message.

@general: I don't think, that fixing one getter call is the right solution as many other getter calls are not fixed and will produce same or similar error messages.

Current Kitodo.Production 2.x is not designed for a multiple tab / browser usage even if this behaviour is expected by users.

matthias-ronge commented 7 years ago

I don’t know what actually causes this behaviour. Just that we can only reproduce it with no user logged in does not mean that it does not happen elsewhen. Just leaving the window open for too long time (lunch break) might cause it as well. Using multiple browser tabs may well confuse the Tomcat, but what I can say is that the session is shared along these tabs. There are no not-logged-in tabs.

JSF was concepted in days where computer memory was measured in MBs. It is designed in a way that it forgets the java model of the page the user requested (which may be up to 800 MB of java objects) once the HTTP response has been sent out, making space to process other requests from other users working with the same application concurrently. When JSF receives a new request from a user, the first thing it does is to restore this java model of the HTTP page the user is on. This is called the restore view phase. During this phase, the request has not yet (and cannot yet) be evaluated. If a getter throws an exception during this phase, JSF cannot deal with it. Fixing the NPE is a prerequisite that the JSF lifecycle can successfully complete the restore view phase, then enter the the apply request phase where the incoming request is evaluated and a possible session time-out can be dealt with.

henning-gerhardt commented 7 years ago

Good to know @matthias-ronge.

I tried your fix, @matthias-ronge but now I get this exception if I request this page without a valid user / browser session.

java.lang.NullPointerException
    at de.sub.goobi.metadaten.Metadaten.isAddNewMetadataGroupLinkShowing(Metadaten.java:3167)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.apache.myfaces.el.PropertyResolverImpl.getProperty(PropertyResolverImpl.java:457)
    at org.apache.myfaces.el.PropertyResolverImpl.getValue(PropertyResolverImpl.java:85)
    at org.apache.myfaces.custom.security.SecurityContextPropertyResolver.getValue(SecurityContextPropertyResolver.java:101)
    at org.apache.myfaces.el.ELParserHelper$MyPropertySuffix.evaluate(ELParserHelper.java:535)
    at org.apache.commons.el.ComplexValue.evaluate(ComplexValue.java:145)
    at org.apache.myfaces.el.ValueBindingImpl.getValue(ValueBindingImpl.java:386)
    at javax.faces.component.UIComponentBase.isRendered(UIComponentBase.java:1078)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:408)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
    at org.apache.myfaces.shared_impl.renderkit.html.HtmlGroupRendererBase.encodeEnd(HtmlGroupRendererBase.java:78)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:419)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:417)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:417)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:417)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
    at org.apache.myfaces.shared_impl.renderkit.html.HtmlGroupRendererBase.encodeEnd(HtmlGroupRendererBase.java:78)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChild(RendererUtils.java:419)
    at org.apache.myfaces.shared_impl.renderkit.RendererUtils.renderChildren(RendererUtils.java:400)
    at org.apache.myfaces.shared_impl.renderkit.html.HtmlGroupRendererBase.encodeEnd(HtmlGroupRendererBase.java:78)
    at javax.faces.component.UIComponentBase.encodeEnd(UIComponentBase.java:539)
    at javax.faces.webapp.UIComponentTag.encodeEnd(UIComponentTag.java:498)
    at javax.faces.webapp.UIComponentTag.doEndTag(UIComponentTag.java:366)
    at org.apache.myfaces.shared_impl.taglib.UIComponentBodyTagBase.doEndTag(UIComponentBodyTagBase.java:57)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_h_005fpanelGroup_005f2(Metadaten2rechts_jsp.java:2782)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_h_005fform_005f1(Metadaten2rechts_jsp.java:2676)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_htm_005ftd_005f4(Metadaten2rechts_jsp.java:2574)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_htm_005ftr_005f3(Metadaten2rechts_jsp.java:2536)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_htm_005ftable_005f2(Metadaten2rechts_jsp.java:2401)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspx_meth_f_005fview_005f0(Metadaten2rechts_jsp.java:1125)
    at org.apache.jsp.pages.Metadaten2rechts_jsp._jspService(Metadaten2rechts_jsp.java:726)
    at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
    at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:439)
    at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:395)
    at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:339)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:747)
    at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:485)
    at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:410)
    at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:337)
    at org.apache.myfaces.context.servlet.ServletExternalContextImpl.dispatch(ServletExternalContextImpl.java:419)
    at org.apache.myfaces.application.jsp.JspViewHandlerImpl.renderView(JspViewHandlerImpl.java:211)
    at org.jenia.faces.template.handler.ViewHandler.renderView(ViewHandler.java:76)
    at org.ajax4jsf.application.ViewHandlerWrapper.renderView(ViewHandlerWrapper.java:108)
    at org.ajax4jsf.application.AjaxViewHandler.renderView(AjaxViewHandler.java:216)
    at org.apache.myfaces.lifecycle.RenderResponseExecutor.execute(RenderResponseExecutor.java:41)
    at org.apache.myfaces.lifecycle.LifecycleImpl.render(LifecycleImpl.java:132)
    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:140)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.ajax4jsf.webapp.BaseXMLFilter.doXmlFilter(BaseXMLFilter.java:141)
    at org.ajax4jsf.webapp.BaseFilter.doFilter(BaseFilter.java:281)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at de.sub.goobi.helper.servletfilter.SessionCounterFilter.doFilter(SessionCounterFilter.java:74)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at de.sub.goobi.helper.servletfilter.HibernateSessionFilter2.doFilter(HibernateSessionFilter2.java:75)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at de.sub.goobi.helper.servletfilter.SecurityCheckFilter.doFilter(SecurityCheckFilter.java:77)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at de.sub.goobi.helper.servletfilter.RequestControlFilter.doFilter(RequestControlFilter.java:147)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:341)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)

Or should I open a new issue for this error?

matthias-ronge commented 7 years ago

No, its realated. I added a new commit to fix it as well.

henning-gerhardt commented 7 years ago

Ok, even with your next fix I get this stacktrace:

java.lang.NullPointerException
    at de.sub.goobi.metadaten.Metadaten.SperrungAktualisieren(Metadaten.java:1781)
    at de.sub.goobi.metadaten.Metadaten.AnsichtAendern(Metadaten.java:200)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
...

How long should we play this game? Until every getter method in this class and after this in next class is fixed? My impression is that Kitodo.Production is written under a condition that valid user session is available.

Would it not be better to check first if requested user session is valid? If this session is not valid any more then display a message for invalid session and that this user has to login again?

henning-gerhardt commented 7 years ago

If there is no other solution possible then I would accept this kind of changes.

matthias-ronge commented 7 years ago

How do you test (which URL)? If I go through the dialog testing this should shorten the circle.

henning-gerhardt commented 7 years ago

My approach was to call this jsf / jsp page direct without any login. This must be repeated for every single jsf page - if this kind of NPE would be corrected as a session timeout could happen on every jsf page.

stweil commented 7 years ago

Would it not be better to check first if requested user session is valid? If this session is not valid any more then display a message for invalid session and that this user has to login again?

I like this approach. Even if we fix a whole lot of null pointer exceptions, we'd still have to present something to the user, and with a lost session there don't remain many options.

matthias-ronge commented 7 years ago

The last NPE @henning-gerhardt reported is in the function that should handle the time-out …

matthias-ronge commented 7 years ago

Updated the related pull request: #602

henning-gerhardt commented 7 years ago

@stweil : did you try @matthias-ronge changes? Does it work for you?

stweil commented 7 years ago

No, I did not try those changes. Applying them needs more preparation for our production system, and I don't have a test system at hand.

henning-gerhardt commented 7 years ago

I tested it on my local development system (direct calling this jsf file) and I did not get this exception message any more. That is all what I can do.

stweil commented 7 years ago

Thanks. Then I think the PR #602 is good and can be merged.

henning-gerhardt commented 7 years ago

Closing this issue as PR #602 is merged.