search

SoftInstigate / restheart

Rapid API Development with MongoDB
https://restheart.org
GNU Affero General Public License v3.0
807 stars 171 forks source link

GET DOCUMENTS RANDOM ERROR #452

Closed WT2 closed 1 year ago

WT2 commented 1 year ago

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:

1) 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

2) 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?

WT2 commented 1 year ago

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.

ujibang commented 1 year ago

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

We are checking it.....

WT2 commented 1 year ago

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

ujibang commented 1 year ago

Can you check the fix with the following snapshot image:

$ docker pull softinstigate/restheart-snapshot:23f6451
WT2 commented 1 year ago

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 https://github.com/SoftInstigate/restheart/commit/23f6451ca10c0d34d7d610104b1d52def7675d9b ! i no longer have that error.

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