ops4j / org.ops4j.pax.web

OSGi R7 Http Service, Whiteboard and Web Applications (OSGi CMPN Release chapters 102, 140 and 128) implementation using Jetty 9, Tomcat 9 or Undertow 2.
https://ops4j1.jira.com/wiki/display/paxweb/Pax+Web
Other
145 stars 184 forks source link

ResourceDelegatingBundleClassLoader lruCache too small [PAXWEB-959] #1238

Closed ops4j-issues closed 8 years ago

ops4j-issues commented 8 years ago

Jan Kreutzfeld created PAXWEB-959

I'm trying to use our application in Karaf 4.0.4 (instead of 3.0.3), but encounter the following exception at runtime:

java.lang.IllegalStateException: Entry.next=null, data[removeIndex]=web/dipdesktop/css/chromeAll.css.dsp=[bundle://65.0:12/web/dipdesktop/css/chromeAll.css.dsp] previous=web/zul/img/grid/column-bg.png=[bundle://283.0:1/web/zul/img/grid/column-bg.png] key=web/js/zk/zk.wpd value=[bundle://277.0:1/web/js/zk/zk.wpd] size=100 maxSize=100 Please check that your keys are immutable, and that you have used synchronization properly. If so, then please report this to dev@commons.apache.org as a bug.
    at org.apache.commons.collections4.map.LRUMap.reuseMapping(LRUMap.java:311)[264:org.ops4j.pax.web.pax-web-spi:4.2.4]
    at org.apache.commons.collections4.map.LRUMap.addMapping(LRUMap.java:276)[264:org.ops4j.pax.web.pax-web-spi:4.2.4]
    at org.apache.commons.collections4.map.AbstractHashedMap.put(AbstractHashedMap.java:288)[264:org.ops4j.pax.web.pax-web-spi:4.2.4]
    at org.ops4j.pax.web.service.spi.util.ResourceDelegatingBundleClassLoader.addToCache(ResourceDelegatingBundleClassLoader.java:115)[264:org.ops4j.pax.web.pax-web-spi:4.2.4]
    at org.ops4j.pax.web.service.spi.util.ResourceDelegatingBundleClassLoader.findResource(ResourceDelegatingBundleClassLoader.java:81)[264:org.ops4j.pax.web.pax-web-spi:4.2.4]
    at java.lang.ClassLoader.getResource(ClassLoader.java:1093)[:1.8.0_65]
    at org.ops4j.pax.swissbox.core.BundleClassLoader.getResource(BundleClassLoader.java:141)[264:org.ops4j.pax.web.pax-web-spi:4.2.4]
    at java.lang.ClassLoader.getResourceAsStream(ClassLoader.java:1304)[:1.8.0_65]
    at org.zkoss.util.resource.ClassLocator.getResourceAsStream(ClassLocator.java:167)[274:zcommon:6.5.7]
    at org.zkoss.web.util.resource.ClassWebResource.getResourceAsStream(ClassWebResource.java:160)[284:zweb:6.5.7]
    at org.zkoss.web.util.resource.ClassWebResource$CWC.getResourceAsStream(ClassWebResource.java:848)[284:zweb:6.5.7]
    at org.zkoss.web.util.resource.ExtendletLoader.load(ExtendletLoader.java:101)[284:zweb:6.5.7]
    at org.zkoss.web.util.resource.ExtendletLoader.load(ExtendletLoader.java:39)[284:zweb:6.5.7]
    at org.zkoss.util.resource.ResourceCache$Info.load(ResourceCache.java:227)[274:zcommon:6.5.7]
    at org.zkoss.util.resource.ResourceCache$Info.<init>(ResourceCache.java:202)[274:zcommon:6.5.7]
    at org.zkoss.util.resource.ResourceCache.get(ResourceCache.java:134)[274:zcommon:6.5.7]
    at org.zkoss.zk.ui.http.WpdExtendlet.retrieve(WpdExtendlet.java:126)[277:zk:6.5.7]
    at org.zkoss.zk.ui.http.WpdExtendlet.service(WpdExtendlet.java:92)[277:zk:6.5.7]
    at org.zkoss.web.util.resource.ClassWebResource.web0(ClassWebResource.java:584)[284:zweb:6.5.7]
    at org.zkoss.web.util.resource.ClassWebResource.web(ClassWebResource.java:570)[284:zweb:6.5.7]
    at org.zkoss.web.util.resource.ClassWebResource.service(ClassWebResource.java:261)[284:zweb:6.5.7]
    at org.zkoss.zk.au.http.DHtmlUpdateServlet.doGet(DHtmlUpdateServlet.java:425)[277:zk:6.5.7]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)[136:javax.servlet-api:3.1.0]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)[136:javax.servlet-api:3.1.0]
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:812)[235:org.eclipse.jetty.servlet:9.2.14.v20151106]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1669)[235:org.eclipse.jetty.servlet:9.2.14.v20151106]
    at de.doubleslash.dip.desktop.util.LoginFilter.doFilter(LoginFilter.java:110)[65:de.doubleslash.quala.components.core.web:19.2.4.SNAPSHOT]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)[235:org.eclipse.jetty.servlet:9.2.14.v20151106]
    at de.doubleslash.common.servletfilter.EncodingFilter.doFilter(EncodingFilter.java:29)[64:de.doubleslash.quala.components.core.utils:6.0.2]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1652)[235:org.eclipse.jetty.servlet:9.2.14.v20151106]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:585)[235:org.eclipse.jetty.servlet:9.2.14.v20151106]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:70)[261:org.ops4j.pax.web.pax-web-jetty:4.2.4]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:577)[233:org.eclipse.jetty.security:9.2.14.v20151106]
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:223)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1127)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:271)[261:org.ops4j.pax.web.pax-web-jetty:4.2.4]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:515)[235:org.eclipse.jetty.servlet:9.2.14.v20151106]
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1061)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80)[261:org.ops4j.pax.web.pax-web-jetty:4.2.4]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.server.Server.handle(Server.java:499)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)[234:org.eclipse.jetty.server:9.2.14.v20151106]
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[226:org.eclipse.jetty.io:9.2.14.v20151106]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[237:org.eclipse.jetty.util:9.2.14.v20151106]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[237:org.eclipse.jetty.util:9.2.14.v20151106]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]

I get alot of those with different keys that cannot be added since the lruCache is full. Its size is set to 100 in the code, which is not enough in this case. Shouldn't this be configurable? Or am I doing something fundamentally wrong for this to happen?
As you can see from the stacktrace, we are using the ZK framework, which is not very OSGi friendly. I extracted the content of the lruCache at the time the exception occured. Maybe it is useful:

web/js/zul/mesh/mold/auxheader.js=[bundle://283.0:1/web/js/zul/mesh/mold/auxheader.js], 
web/js/zul/box/Box.js=[bundle://283.0:1/web/js/zul/box/Box.js], 
web/js/zul/box/mold/hbox.js=[bundle://283.0:1/web/js/zul/box/mold/hbox.js], 
web/js/zul/box/mold/vbox.js=[bundle://283.0:1/web/js/zul/box/mold/vbox.js], 
web/js/zul/box/Splitter.js=[bundle://283.0:1/web/js/zul/box/Splitter.js], 
web/js/zul/box/mold/splitter.js=[bundle://283.0:1/web/js/zul/box/mold/splitter.js], 
web/js/zul/box/Hlayout.js=[bundle://283.0:1/web/js/zul/box/Hlayout.js], 
web/js/zul/box/mold/layout.js=[bundle://283.0:1/web/js/zul/box/mold/layout.js], 
web/js/zul/box/Vlayout.js=[bundle://283.0:1/web/js/zul/box/Vlayout.js], 
web/js/zul/mesh/Frozen.js=[bundle://283.0:1/web/js/zul/mesh/Frozen.js], 
web/js/zul/mesh/mold/frozen.js=[bundle://283.0:1/web/js/zul/mesh/mold/frozen.js], 
web/zul/img/splt/colps-t.png=[bundle://283.0:1/web/zul/img/splt/colps-t.png], 
web/dipdesktop/images/layout/splt/ds-splt-v.png=[bundle://65.0:12/web/dipdesktop/images/layout/splt/ds-splt-v.png], 
web/zul/img/grid/column-bg.png=[bundle://283.0:1/web/zul/img/grid/column-bg.png], 
web/zul/img/grid/head-bg.png=[bundle://283.0:1/web/zul/img/grid/head-bg.png], 
web/dipdesktop/images/layout/splt/ds-colps-l.png=[bundle://65.0:12/web/dipdesktop/images/layout/splt/ds-colps-l.png], 
web/zul/img/grid/arrows.png=[bundle://283.0:1/web/zul/img/grid/arrows.png], 
web/dipdesktop/images/layout/listbox/check-inactive.png=[bundle://65.0:12/web/dipdesktop/images/layout/listbox/check-inactive.png], 
web/dipdesktop/images/layout/splt/ds-colps-r.png=[bundle://65.0:12/web/dipdesktop/images/layout/splt/ds-colps-r.png],
web/dipdesktop/images/layout/listbox/check-active.png=[bundle://65.0:12/web/dipdesktop/images/layout/listbox/check-active.png], 
web/dipdesktop/css/chromeAll.css.dsp=[bundle://65.0:12/web/dipdesktop/css/chromeAll.css.dsp], 
metainfo/mesg/msgzul_de_DE.properties=[], 
metainfo/mesg/msgzul_de.properties=[bundle://283.0:1/metainfo/mesg/msgzul_de.properties], 
web/js/zk/lang/msgzk_de_DE.js=[], 
web/js/zk/lang/msgzk_de.js=[bundle://277.0:1/web/js/zk/lang/msgzk_de.js], 
web/js/zul/lang/msgzul_de_DE.js=[], 
web/js/zul/lang/msgzul_de.js=[bundle://283.0:1/web/js/zul/lang/msgzul_de.js], 
web/dipdesktop/images/layout/listbox/check-active-over.png=[bundle://65.0:12/web/dipdesktop/images/layout/listbox/check-active-over.png], 
web/dipdesktop/images/layout/menu/arrow-left.gif=[bundle://65.0:12/web/dipdesktop/images/layout/menu/arrow-left.gif], 
web/dipdesktop/images/layout/icons/arrow-toggle.png=[bundle://65.0:12/web/dipdesktop/images/layout/icons/arrow-toggle.png], 
web/dipdesktop/images/icons/notification/notif-success.png=[bundle://65.0:12/web/dipdesktop/images/icons/notification/notif-success.png], 
web/dipdesktop/images/icons/drive/pencil_16x16.png=[bundle://65.0:12/web/dipdesktop/images/icons/drive/pencil_16x16.png], 
web/dipdesktop/images/icons/drive/folder_128x128.png=[bundle://65.0:12/web/dipdesktop/images/icons/drive/folder_128x128.png], 
web/dipdesktop/images/icons/drive/check_16x16.png=[bundle://65.0:12/web/dipdesktop/images/icons/drive/check_16x16.png], 
web/dipdesktop/images/icons/upload-loader.gif=[bundle://65.0:12/web/dipdesktop/images/icons/upload-loader.gif], 
META-INF/services/javax.xml.datatype.DatatypeFactory=[], 
web/dipdesktop/images/icons/drive/supported_types/image_24x24.png=[bundle://65.0:12/web/dipdesktop/images/icons/drive/supported_types/image_24x24.png], 
META-INF/services/javax.xml.parsers.SAXParserFactory=[], 
META-INF/services/org.apache.xerces.xni.parser.XMLParserConfiguration=[], 
bsh.java=[], 
org/zkoss/zul/Object.java=[], 
org/zkoss/zk/ui/Object.java=[], 
org/zkoss/zk/ui/event/Object.java=[], 
Component.java=[], 
org/zkoss/calendar/Component.java=[], 
org/zkoss/calendar/impl/Component.java=[], 
org/zkoss/calendar/api/Component.java=[], 
org/zkoss/calendar/event/Component.java=[], 
org/zkoss/zkplus/databind/Component.java=[], 
org/zkoss/zkmax/zul/Component.java=[], 
org/zkoss/zkex/zul/Component.java=[], 
org/zkoss/bind/Component.java=[], 
org/zkoss/zul/Component.java=[], 
String.java=[], 
org/zkoss/calendar/String.java=[], 
org/zkoss/calendar/impl/String.java=[], 
org/zkoss/calendar/api/String.java=[], 
org/zkoss/calendar/event/String.java=[], 
org/zkoss/zkplus/databind/String.java=[], 
org/zkoss/zkmax/zul/String.java=[],
org/zkoss/zkex/zul/String.java=[], 
org/zkoss/bind/String.java=[], 
org/zkoss/zul/String.java=[], 
org/zkoss/zk/ui/String.java=[], 
org/zkoss/zk/ui/event/String.java=[], 
de.java=[], 
org/zkoss/calendar/de.java=[], 
org/zkoss/calendar/impl/de.java=[],
org/zkoss/calendar/api/de.java=[], 
org/zkoss/calendar/event/de.java=[], 
org/zkoss/zkplus/databind/de.java=[], 
org/zkoss/zkmax/zul/de.java=[], 
org/zkoss/zkex/zul/de.java=[], 
org/zkoss/bind/de.java=[], 
org/zkoss/zul/de.java=[], 
org/zkoss/zk/ui/de.java=[], 
org/zkoss/zk/ui/event/de.java=[], 
java/lang/de.java=[], 
java/util/de.java=[], 
de/doubleslash.java=[], 
de/doubleslash/standardcomponents.java=[], 
de/doubleslash/standardcomponents/iface.java=[], 
org.java=[], 
org/zkoss/calendar/org.java=[], 
org/zkoss/calendar/impl/org.java=[], 
org/zkoss/calendar/api/org.java=[], 
org/zkoss/calendar/event/org.java=[], 
org/zkoss/zkplus/databind/org.java=[], 
org/zkoss/zkmax/zul/org.java=[], 
org/zkoss/zkex/zul/org.java=[], 
org/zkoss/bind/org.java=[], 
org/zkoss/zul/org.java=[], 
org/zkoss/zk/ui/org.java=[], 
org/zkoss/zk/ui/event/org.java=[], 
java/lang/org.java=[], 
java/util/org.java=[], 
org/zkoss.java=[], 
org/zkoss/util.java=[], 
org/zkoss/util/resource.java=[], 
META-INF/services/org.zkoss.zel.ExpressionFactory=[]

Affects: 4.2.4 Fixed in: 4.2.6, 4.2.7, 6.0.0 Votes: 0, Watches: 3

ops4j-issues commented 8 years ago

Jan Kreutzfeld commented

FYI: for testing purposes, i recompiled the pax-web-spi 4.2.4 bundle with a cache max size of 10000. Now, the actual size of the cache is roughly 500 and my application works fine.

ops4j-issues commented 8 years ago

Achim Nierbeck commented

thanks for the input, right now I'm thinking of a nice way to get the configs from the main config file there ... that would need to be passed a long chain ... so I need to find something smoother :wink:

ops4j-issues commented 8 years ago

Christoph Läubrich commented

Just wondering: Should a LRUCache not vanish entries when it is full and maybe reload them later?

ops4j-issues commented 8 years ago

Achim Nierbeck commented

yes ... that's something that made me wonder too ...
especially the message "Please check that your keys are immutable" seems to be strange, oth it seems to be 100 unique keys ...

ops4j-issues commented 8 years ago

Christoph Läubrich commented

Maybe Jan Kreutzfeld cann check if there are any duplicate resources? Its seems to replace chromeAll.css or something similar but I'm not that familiar with LRUCache.
For Caching purpose I use Google Guava Cache that has a nice Loader interface and several options for evicting entries by size, time or access contraints, but introducing a new dependecy might not be wanted ...

It still might be a sync-issue as the exception suggested.

ops4j-issues commented 8 years ago

Achim Nierbeck commented

Just did take a closer look on the exported cache list.
I find it rather strange that it actually contains a lot of entries where there are keys but no values bound to it. Especially something like String.java=[]
I would make sure those entries are actually not added to the cache, maybe we can work on those to actually skip to add inside pax-web

ops4j-issues commented 8 years ago

Achim Nierbeck commented

master: https://github.com/ops4j/org.ops4j.pax.web/commit/9f24df7f51c568f8f8bd21b890861b55f05c0411
4.2.x: https://github.com/ops4j/org.ops4j.pax.web/commit/1dd61b03c5873933bd7fe3e77c62004fd7d2585a

ops4j-issues commented 8 years ago

Jan Kreutzfeld commented

The problem still occurs after your fix. It might very well be a synchronization issue. When adding the synchronized keyword to the ResourceDelegatingBundleClassLoader#addToCache method, i can no longer reproduce the exception. I don't know about the performance impact though.

protected synchronized void addToCache(String name, Vector<URL> resources) {
    lruCache.put(name, resources);
}
ops4j-issues commented 8 years ago

Achim Nierbeck commented

adding synchronization:
master:
https://github.com/ops4j/org.ops4j.pax.web/commit/022e0d507bb2d5042eaea25ed2432123e774536f

ops4j-issues commented 8 years ago

Achim Nierbeck commented

4.2.x:
https://github.com/ops4j/org.ops4j.pax.web/commit/ef316f45d330b0c146e7010c879ef80106fef6fb

ops4j-issues commented 8 years ago

Jon Anstey commented

Released under 4.2.7.