[AAA-174] Intermittent failure when listing all users via REST Created: 17/May/18  Updated: 22/Mar/19  Resolved: 22/Mar/19

Status: Resolved
Project: aaa
Component/s: None
Affects Version/s: Fluorine, Neon, Sodium
Fix Version/s: Sodium, Fluorine SR3, Neon SR1

Type: Bug Priority: Medium
Reporter: Richard Kosegi Assignee: Richard Kosegi
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File fluorine.karaf.log     File neon.karaf.log    

 Description   

Sometimes, when trying to access endpoint `auth/v1/users`, I got HTTP500 as a response:

error: There was an internal error getting the user details:  status: 500

 

To reproduce it, just use heavy load:

seq 10 | parallel -n0 --gnu -j 10 curl -u admin:admin -v http://172.17.0.2:8181/auth/v1/users

Full trace:

2018-05-17 12:14:39,906 | ERROR | qtp1906499442-71 | UserHandler                      | 190 - org.opendaylight.aaa.shiro - 0.7.1 | There was an internal error getting the user
org.opendaylight.aaa.api.IDMStoreException: org.opendaylight.aaa.datastore.h2.StoreException: Cannot connect to database server
    at org.opendaylight.aaa.datastore.h2.H2Store.getUsers(H2Store.java:201) [190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.shiro.idm.UserHandler.getUsers(UserHandler.java:91) [190:org.opendaylight.aaa.shiro:0.7.1]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$ResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:205) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.uri.rules.ResourceClassRule.accept(ResourceClassRule.java:108) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1542) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1473) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1419) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1409) [17:com.sun.jersey.jersey-server:1.19.4]
    at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:409) [18:com.sun.jersey.servlet:1.19.4]
    at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:558) [18:com.sun.jersey.servlet:1.19.4]
    at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:733) [18:com.sun.jersey.servlet:1.19.4]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [71:javax.servlet-api:3.1.0]
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1772) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.eclipse.jetty.websocket.server.WebSocketUpgradeFilter.doFilter(WebSocketUpgradeFilter.java:205) [171:org.eclipse.jetty.websocket.server:9.3.21.v20170918]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:308) [162:org.eclipse.jetty.servlets:9.3.21.v20170918]
    at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:262) [162:org.eclipse.jetty.servlets:9.3.21.v20170918]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:61) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.AdviceFilter.executeChain(AdviceFilter.java:108) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.AdviceFilter.doFilterInternal(AdviceFilter.java:137) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.ProxiedFilterChain.doFilter(ProxiedFilterChain.java:66) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:449) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90) [142:org.apache.shiro.core:1.3.2]
    at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83) [142:org.apache.shiro.core:1.3.2]
    at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:383) [142:org.apache.shiro.core:1.3.2]
    at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362) [143:org.apache.shiro.web:1.3.2]
    at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125) [143:org.apache.shiro.web:1.3.2]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.opendaylight.aaa.filterchain.filters.CustomFilterAdapter.doFilter(CustomFilterAdapter.java:80) [189:org.opendaylight.aaa.filterchain:0.7.1]
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1751) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [343:org.ops4j.pax.web.pax-web-jetty:6.0.9]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [158:org.eclipse.jetty.security:9.3.21.v20170918]
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [343:org.ops4j.pax.web.pax-web-jetty:6.0.9]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [161:org.eclipse.jetty.servlet:9.3.21.v20170918]
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [343:org.ops4j.pax.web.pax-web-jetty:6.0.9]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.server.Server.handle(Server.java:534) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [160:org.eclipse.jetty.server:9.3.21.v20170918]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [152:org.eclipse.jetty.io:9.3.21.v20170918]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [152:org.eclipse.jetty.io:9.3.21.v20170918]
    at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [152:org.eclipse.jetty.io:9.3.21.v20170918]
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [163:org.eclipse.jetty.util:9.3.21.v20170918]
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [163:org.eclipse.jetty.util:9.3.21.v20170918]
    at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [163:org.eclipse.jetty.util:9.3.21.v20170918]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [163:org.eclipse.jetty.util:9.3.21.v20170918]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [163:org.eclipse.jetty.util:9.3.21.v20170918]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.opendaylight.aaa.datastore.h2.StoreException: Cannot connect to database server
    at org.opendaylight.aaa.datastore.h2.AbstractStore.dbConnect(AbstractStore.java:82) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.AbstractStore.listAll(AbstractStore.java:120) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.UserStore.getUsers(UserStore.java:80) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.H2Store.getUsers(H2Store.java:198) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    ... 71 more
Caused by: org.h2.jdbc.JdbcSQLException: The object is already closed [90007-196]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.h2.message.DbException.get(DbException.java:179) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.h2.message.DbException.get(DbException.java:155) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.h2.message.DbException.get(DbException.java:144) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1481) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1459) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:335) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.AbstractStore.dbConnect(AbstractStore.java:68) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.AbstractStore.listAll(AbstractStore.java:120) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.UserStore.getUsers(UserStore.java:80) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    at org.opendaylight.aaa.datastore.h2.H2Store.getUsers(H2Store.java:198) ~[190:org.opendaylight.aaa.shiro:0.7.1]
    ... 71 more
2018-05-17 12:14:40,170 | ERROR | qtp1906499442-71 | IDMError                         | 185 - org.opendaylight.aaa.authn-api - 0.7.1 | error: There was an internal error getting the user details:  status: 500

 

 

 Comments   
Comment by Robert Varga [ 21/Mar/19 ]

rkosegi is thi still reproducible with Fluorine-or-later?

Comment by Richard Kosegi [ 21/Mar/19 ]

Hi rovarga, replicated on Fluorine, Neon and master using

"seq 100 |  parallel -n0 --gnu -j 10 curl -u admin:admin http://localhost:8181/auth/v1/users"

Attached logs from 9.1 and 10.0

I can take a look at fixing it

Comment by Robert Varga [ 21/Mar/19 ]

Thank would be awesome, thanks!

Comment by Richard Kosegi [ 22/Mar/19 ]

Problem seems to be here https://github.com/opendaylight/aaa/blob/master/aaa-shiro/impl/src/main/java/org/opendaylight/aaa/datastore/h2/IdmLightSimpleConnectionProvider.java#L33

Same instance of Connection can be obtain by multiple threads, but once first thread call #close() on it, other threads will fail to use it further.

Comment by Robert Varga [ 22/Mar/19 ]

Looks okay, thanks for the fix.

Generated at Wed Feb 07 19:08:49 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.