GET DOCUMENTS RANDOM ERROR

Question

GET DOCUMENTS RANDOM ERROR

WT2 opened this issue 2 years ago · 5 comments

Hello Guys

restheart:7.3.2
mongo:6.0

I closed the other issue and opened a new one with more precise issue and logs.
I have trouble with multiple "paged" get focuments calls on same collection in short time, it randomly fails. It works 2, 3 times and 4th time it will fail with bellow exception.

EXCEPTION:

15:40:00.661 [XNIO-1 task-3] ^[[34mINFO ^[[0;39m org.restheart.handlers.RequestLogger - GET http://api_dynamic/api/inventory/fruits/_size from /172.18.0.3:45466 => status=^[[32;1m200^[[m elapsed=9ms contentLength=31 username=opsbatch roles=[base]
15:40:00.677 [XNIO-1 task-3] ^[[1;31mERROR^[[0;39m o.r.mongodb.handlers.ErrorHandler - Error handling the request
java.lang.IndexOutOfBoundsException: toIndex = 2
at java.base/java.util.AbstractList.subListRangeCheck(Unknown Source)
at java.base/java.util.ArrayList.subList(Unknown Source)
at org.restheart.mongodb.db.Collections.getCollectionData(Collections.java:230)
at org.restheart.mongodb.db.Databases.getCollectionData(Databases.java:496)
at org.restheart.mongodb.handlers.collection.GetCollectionHandler.handleRequest(GetCollectionHandler.java:118)
at org.restheart.mongodb.handlers.RequestDispatcherHandler.handleRequest(RequestDispatcherHandler.java:134)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.mongodb.handlers.injectors.ETagPolicyInjector.handleRequest(ETagPolicyInjector.java:73)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.mongodb.handlers.injectors.ClientSessionInjector.handleRequest(ClientSessionInjector.java:99)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.mongodb.handlers.OptionsHandler.handleRequest(OptionsHandler.java:83)
at org.restheart.mongodb.handlers.ErrorHandler.handleRequest(ErrorHandler.java:74)
at org.restheart.handlers.PipelinedWrappingHandler.handleRequest(PipelinedWrappingHandler.java:121)
at io.undertow.server.handlers.PathHandler.handleRequest(PathHandler.java:104)
at org.restheart.handlers.PipelinedWrappingHandler.handleRequest(PipelinedWrappingHandler.java:121)
at org.restheart.mongodb.MongoService.handle(MongoService.java:126)
at org.restheart.mongodb.MongoService.handle(MongoService.java:72)
at org.restheart.handlers.ServiceWrapper.handleRequest(PipelinedWrappingHandler.java:139)
at org.restheart.handlers.PipelinedWrappingHandler.handleRequest(PipelinedWrappingHandler.java:121)
at io.undertow.server.handlers.encoding.EncodingHandler.handleRequest(EncodingHandler.java:72)
at org.restheart.handlers.ConfigurableEncodingHandler.handleRequest(ConfigurableEncodingHandler.java:81)
at org.restheart.handlers.PipelinedWrappingHandler.handleRequest(PipelinedWrappingHandler.java:121)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.QueryStringRebuilder.handleRequest(QueryStringRebuilder.java:92)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.RequestInterceptorsExecutor.handleRequest(RequestInterceptorsExecutor.java:149)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.security.handlers.AuthorizersHandler.handleRequest(AuthorizersHandler.java:65)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.injectors.TokenInjector.handleRequest(TokenInjector.java:62)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.security.handlers.AuthenticationCallHandler.handleRequest(AuthenticationCallHandler.java:110)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:79)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.security.handlers.AuthenticatorMechanismsHandler.handleRequest(AuthenticatorMechanismsHandler.java:59)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:74)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.security.handlers.SecurityHandler.handleRequest(SecurityHandler.java:58)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.QueryStringRebuilder.handleRequest(QueryStringRebuilder.java:92)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.RequestInterceptorsExecutor.handleRequest(RequestInterceptorsExecutor.java:149)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.injectors.XPoweredByInjector.handleRequest(XPoweredByInjector.java:63)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.CORSHandler.handleRequest(CORSHandler.java:90)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.ServiceExchangeInitializer.handleRequest(ServiceExchangeInitializer.java:103)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.BeforeExchangeInitInterceptorsExecutor.handleRequest(BeforeExchangeInitInterceptorsExecutor.java:85)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.RequestLogger.handleRequest(RequestLogger.java:86)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.TracingInstrumentationHandler.handleRequest(TracingInstrumentationHandler.java:62)
at org.restheart.handlers.TracingInstrumentationHandler.handleRequest(TracingInstrumentationHandler.java:62)
at org.restheart.handlers.PipelinedHandler.next(PipelinedHandler.java:80)
at org.restheart.handlers.WorkingThreadsPoolDispatcher.handleRequest(WorkingThreadsPoolDispatcher.java:70)
at org.restheart.handlers.ErrorHandler.handleRequest(ErrorHandler.java:61)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:393)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:859)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
at java.base/java.lang.Thread.run(Unknown Source)

Here are the calls generating the exception:

this one worked:

REQUEST METHOD                GET
REQUEST URL                   https://XXXXXXXXXXXXXXX/api/inventory/fruits?keys=%7B,%22name%22:1,%22family%22:1,%7D&cache&page=1&pagesize=1000
REQUEST HEADERS               {'X-Is-CloudRun': 'TRUE', 'accept': '*/*', 'User-Agent': 'python-requests/2.27.1', 'Connection': 'keep-alive', 'X-Was-LoadBalanced': 'TRUE', 'Cookie': 'NODEID=NODE1', 'content-type': 'application/json', 'Authorization': 'Basic XXXXXXXXXXXXXXX', 'Accept-Encoding': 'gzip, deflate'}
REQUEST BODY                  None
RESPONSE HEADERS              {'content-length': '250', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'auth-token-location': '/tokens/opsbatch', 'auth-token-valid-until': '2023-03-24T09:19:54.769004401Z', 'content-encoding': 'gzip', 'x-powered-by': 'origin', 'access-control-expose-headers': 'Location, ETag, Auth-Token, Auth-Token-Valid-Until, Auth-Token-Location, X-Powered-By', 'server': 'nginx', 'auth-token': 'XXXXXXXXXXXXXXX', 'content-security-policy': "default-src 'self' https: wss: data: blob: 'unsafe-inline';", 'etag': '6419ec0c3f7f2c4e18fcd31e', 'x-xss-protection': '1;mode=block', 'access-control-allow-credentials': 'true', 'date': 'Fri, 24 Mar 2023 09:04:54 GMT', 'access-control-allow-origin': '*', 'referrer-policy': 'strict-origin-when-cross-origin', 'content-type': 'application/json', 'x-frame-options': 'SAMEORIGIN', 'x-content-type-options': 'nosniff', 'permissions-policy': 'interest-cohort=()'}
RESPONSE COOKIES              {}
RESPONSE CONTENT              [{}] --> HERE IT GIVES ME MY OBJECTS
RESPONSE STATUS CODE          200
RESPONSE ERROR MESSAGE
CREATED                       False
UPDATED                       False
DELETED                       False
RETRIEVED                     True
SUCCESS                       True
ID                            None

this one did not work (the call was done right after the other):

REQUEST METHOD                GET
REQUEST URL                   https://XXXXXXXXXXXXXXX/api/inventory/fruits?keys=%7B,%22name%22:1,%22family%22:1,%7D&cache&page=1&pagesize=1000
REQUEST HEADERS               {'X-Is-CloudRun': 'TRUE', 'accept': '*/*', 'User-Agent': 'python-requests/2.27.1', 'Connection': 'keep-alive', 'X-Was-LoadBalanced': 'TRUE', 'Cookie': 'NODEID=NODE2', 'content-type': 'application/json', 'Authorization': 'Basic m', 'Accept-Encoding': 'gzip, deflate'}
REQUEST BODY                  None
RESPONSE HEADERS              {'content-length': '174', 'strict-transport-security': 'max-age=31536000; includeSubDomains; preload', 'auth-token-location': '/tokens/opsbatch', 'auth-token-valid-until': '2023-03-24T09:19:56.724594290Z', 'content-encoding': 'gzip', 'x-powered-by': 'origin', 'access-control-expose-headers': 'Location, ETag, Auth-Token, Auth-Token-Valid-Until, Auth-Token-Location, X-Powered-By', 'server': 'nginx', 'auth-token': 'XXXXXXXXXXXXXXX', 'content-security-policy': "default-src 'self' https: wss: data: blob: 'unsafe-inline';", 'x-xss-protection': '1;mode=block', 'access-control-allow-credentials': 'true', 'date': 'Fri, 24 Mar 2023 09:04:56 GMT', 'access-control-allow-origin': '*', 'referrer-policy': 'strict-origin-when-cross-origin', 'content-type': 'application/json', 'x-frame-options': 'SAMEORIGIN', 'x-content-type-options': 'nosniff', 'permissions-policy': 'interest-cohort=()'}
RESPONSE COOKIES              {}
RESPONSE CONTENT              {"http status code":500,"http status description":"Internal Server Error","message":"Error handling the request, see log for more information","exception":"java.lang.IndexOutOfBoundsException","exception message":"toIndex = 2"}
RESPONSE STATUS CODE          500
RESPONSE ERROR MESSAGE        Internal Server Error - Error handling the request, see log for more information
CREATED                       False
UPDATED                       False
DELETED                       False
RETRIEVED                     False
SUCCESS                       False
ID                            None
ETAG                          None

Can you please help?

Answer 1 · 2023-03-24T09:20:53.000Z

Jus to add, here i have two nodes the two requests was done randomly on different nodes, but i can have the error if it falls on the same node.

Answer 2 · 2023-03-27T09:13:56.000Z

It must be an issue with caching, that is a quite recent feature.

We are checking it.....

Answer 3 · 2023-03-27T11:31:46.000Z

Yep i confirm, if i disable the cache, it works perfectly

Answer 4 · 2023-03-27T17:23:24.000Z

Can you check the fix with the following snapshot image:

$ docker pull softinstigate/restheart-snapshot:23f6451

Answer 5 · 2023-03-28T10:55:49.000Z

Hi @ujibang
YES! thanks it corrects. I set this snapshot only on one of my two nodes. i still reproduce on the node with 7.3.3 and no longer on the snapshot 23f6451 ! i no longer have that error.

Here (in comparison with the issue #454) i was able to reproduce even with default set to preferredPrimary