search

SoftInstigate / restheart

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

404 from time to time #191

Closed tunguski closed 6 years ago

tunguski commented 7 years ago

I'm testing restheart using restheart-docker. My simple app is GETting and PUTing same document all the time. There is no explicit remove operation in this workflow.

The problem is that from time to time I get 404. I cannot understand what's wrong. I'm not sure is it a bug or I'm missing something here. Could someone help me resolve this issue please? I will be happy to provide any input that may help. Below I've described environment and sample log that I see as the output.

There is one 404 in the middle of log. Next GET request is returning proper document for some reason. PUT requests always provide document with single field modified (last user access date). There is no other app connecting to that mongo, no manual requests too.

Thanks in advance!

Environment:

restheart 3.0.0
mongodb   3.4.2
docker    0.12.6

Example restheart log:

restheart    | 19:43:34.987 [XNIO-1 task-8] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ppp from /172.18.0.1:38486 => status=200 elapsed=3ms contentLength=8679 username=admin roles=[users, admins]
restheart    | 19:43:35.004 [XNIO-1 task-1] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ppp from /172.18.0.1:38494 => status=200 elapsed=2ms contentLength=8679 username=admin roles=[users, admins]
restheart    | 19:43:35.008 [XNIO-1 task-7] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/ppp from /172.18.0.1:38492 => status=200 elapsed=6ms contentLength=0 username=admin roles=[users, admins]
restheart    | 19:43:35.060 [XNIO-1 task-3] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/ppp from /172.18.0.1:38508 => status=200 elapsed=10ms contentLength=0 username=admin roles=[users, admins]
restheart    | 19:43:35.557 [XNIO-1 task-2] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ppp from /172.18.0.1:38516 => status=200 elapsed=5ms contentLength=8681 username=admin roles=[users, admins]
restheart    | 19:43:35.567 [XNIO-1 task-4] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ppp from /172.18.0.1:38524 => status=404 elapsed=1ms contentLength=104 username=admin roles=[users, admins]
restheart    | 19:43:35.567 [XNIO-1 task-5] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/ppp from /172.18.0.1:38520 => status=200 elapsed=3ms contentLength=0 username=admin roles=[users, admins]
restheart    | 19:43:35.572 [XNIO-1 task-6] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ppp from /172.18.0.1:38528 => status=200 elapsed=2ms contentLength=8681 username=admin roles=[users, admins]
ujibang commented 7 years ago

Can you please try with latest snapshot build?

We fixed an issue related to a not thread safe class...

tunguski commented 7 years ago

Could you specify what version should I use in docker-compose to do that? If it is manual process is there instruction?

tunguski commented 7 years ago

I've built branch 3.0.x (7adcae0497683057f83f0ed37b8372fd6dbd4d48), added result to docker-compose (after small modification in Dockerfile - removed downloading, take artifact from local file).

It is possible that this problem is fixed as I couldn't reproduce the bug. Still it is only a manual testing and I cannot confirm reliably.

There is one more thing that seems problematic. Some requests report duplicate key. It is strange as I do only PUTs assuming that it is UPSERT. The problem seems to be corelated as it is only once in a while and next GET requests work fine.

Here is a sample log I've encountered:

restheart    | 22:50:12.863 [XNIO-1 task-1] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ttt from /172.18.0.1:58206 => status=200 elapsed=3ms contentLength=4487 username=admin roles=[users, admins]
restheart    | 22:50:12.875 [XNIO-1 task-3] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/ttt from /172.18.0.1:58210 => status=200 elapsed=6ms contentLength=0 username=admin roles=[users, admins]
restheart    | 22:50:12.883 [XNIO-1 task-4] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ttt from /172.18.0.1:58214 => status=200 elapsed=2ms contentLength=4487 username=admin roles=[users, admins]
restheart    | 22:50:13.145 [XNIO-1 task-6] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ttt from /172.18.0.1:58226 => status=200 elapsed=4ms contentLength=4487 username=admin roles=[users, admins]
restheart    | 22:50:13.146 [XNIO-1 task-5] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ttt from /172.18.0.1:58230 => status=200 elapsed=3ms contentLength=4487 username=admin roles=[users, admins]
restheart    | 22:50:13.160 [XNIO-1 task-8] ERROR org.restheart.handlers.ErrorHandler - Error handling the request
restheart    | com.mongodb.MongoCommandException: Command failed with error 11000: 'E11000 duplicate key error collection: testdb.games index: _id_ dup key: { : "ttt" }' on server mongodb:27017. The full response is { "ok" : 0.0, "errmsg" : "E11000 duplicate key error collection: testdb.games index: _id_ dup key: { : \"ttt\" }", "code" : 11000, "codeName" : "DuplicateKey" }
restheart    |  at com.mongodb.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:115)
restheart    |  at com.mongodb.connection.CommandProtocol.execute(CommandProtocol.java:114)
restheart    |  at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:168)
restheart    |  at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:289)
restheart    |  at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:176)
restheart    |  at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:216)
restheart    |  at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:153)
restheart    |  at com.mongodb.operation.FindAndUpdateOperation$1.call(FindAndUpdateOperation.java:335)
restheart    |  at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:422)
restheart    |  at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:413)
restheart    |  at com.mongodb.operation.FindAndUpdateOperation.execute(FindAndUpdateOperation.java:331)
restheart    |  at com.mongodb.Mongo.execute(Mongo.java:845)
restheart    |  at com.mongodb.Mongo$2.execute(Mongo.java:828)
restheart    |  at com.mongodb.MongoCollectionImpl.findOneAndUpdate(MongoCollectionImpl.java:435)
restheart    |  at org.restheart.db.DAOUtils.updateDocument(DAOUtils.java:163)
restheart    |  at org.restheart.db.DAOUtils.updateDocument(DAOUtils.java:100)
restheart    |  at org.restheart.db.DocumentDAO.upsertDocument(DocumentDAO.java:109)
restheart    |  at org.restheart.handlers.document.PutDocumentHandler.handleRequest(PutDocumentHandler.java:116)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.metadata.BeforeWriteCheckMetadataHandler.handleRequest(BeforeWriteCheckMetadataHandler.java:79)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.metadata.AbstractTransformerMetadataHandler.handleRequest(AbstractTransformerMetadataHandler.java:63)
restheart    |  at org.restheart.handlers.RequestDispacherHandler.handleRequest(RequestDispacherHandler.java:468)
restheart    |  at org.restheart.handlers.injectors.CollectionPropsInjectorHandler.handleRequest(CollectionPropsInjectorHandler.java:98)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.injectors.DbPropsInjectorHandler.handleRequest(DbPropsInjectorHandler.java:92)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.injectors.AccountInjectorHandler.handleRequest(AccountInjectorHandler.java:56)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.AccessManagerHandler.handleRequest(AccessManagerHandler.java:55)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.AuthTokenInjecterHandler.handleRequest(AuthTokenInjecterHandler.java:70)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.AuthenticationCallHandler.handleRequest(AuthenticationCallHandler.java:54)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:55)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:61)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:85)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.SecurityHandler.handleRequest(SecurityHandler.java:50)
restheart    |  at org.restheart.security.handlers.SecurityHandlerDispacher.handleRequest(SecurityHandlerDispacher.java:60)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.injectors.BodyInjectorHandler.handleRequest(BodyInjectorHandler.java:334)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.OptionsHandler.handleRequest(OptionsHandler.java:58)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.handlers.injectors.RequestContextInjectorHandler.handleRequest(RequestContextInjectorHandler.java:647)
restheart    |  at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:136)
restheart    |  at org.restheart.security.handlers.CORSHandler.handleRequest(CORSHandler.java:88)
restheart    |  at org.restheart.handlers.RequestLoggerHandler.handleRequest(RequestLoggerHandler.java:87)
restheart    |  at org.restheart.handlers.PipedHttpHandler.handleRequest(PipedHttpHandler.java:89)
restheart    |  at io.undertow.server.handlers.PathHandler.handleRequest(PathHandler.java:94)
restheart    |  at io.undertow.server.handlers.HttpContinueAcceptingHandler.handleRequest(HttpContinueAcceptingHandler.java:78)
restheart    |  at org.restheart.handlers.ErrorHandler.handleRequest(ErrorHandler.java:69)
restheart    |  at io.undertow.server.handlers.encoding.EncodingHandler.handleRequest(EncodingHandler.java:66)
restheart    |  at org.restheart.handlers.GzipEncodingHandler.handleRequest(GzipEncodingHandler.java:74)
restheart    |  at io.undertow.server.Connectors.executeRootHandler(Connectors.java:210)
restheart    |  at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:809)
restheart    |  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
restheart    |  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
restheart    |  at java.lang.Thread.run(Thread.java:745)
restheart    | 22:50:13.160 [XNIO-1 task-7] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/ttt from /172.18.0.1:58236 => status=201 elapsed=5ms contentLength=0 username=admin roles=[users, admins]
restheart    | 22:50:13.163 [XNIO-1 task-8] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/ttt from /172.18.0.1:58238 => status=500 elapsed=8ms contentLength=415 username=admin roles=[users, admins]
restheart    | 22:50:13.438 [XNIO-1 task-2] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/ttt from /172.18.0.1:58254 => status=200 elapsed=2ms contentLength=4487 username=admin roles=[users, admins]
ujibang commented 7 years ago

If you are testing with concurrent PUT requests, you might incur in this issues.

As you know, mongodb cannot guarantee atomicity, see write-operations-atomicity in mongodb documentations.

a PUT in restheart actually involves few db operations and concurrent requests might lead to ghost writes. in practical terms, if you really need to update the same document concurrently at milliseconds speed, you might want to use ETAG check feature provided by RESTHeart, see ETAG in RESTHeart documentation

tunguski commented 7 years ago

Yes, you are right. Thanks for helpful suggestions!

tunguski commented 7 years ago

I've switched to official 3.0.1 version and I see the same problem (404) all the time.

One additional question: what does "contentLength=-1" mean in case of restheart?

restheart    | 08:59:44.567 [XNIO-1 task-1] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/bbb from /172.18.0.1:44456 => status=200 elapsed=5ms contentLength=-1 username=admin roles=[users, admins]
restheart    | 08:59:44.585 [XNIO-1 task-6] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/bbb from /172.18.0.1:44460 => status=200 elapsed=6ms contentLength=0 username=admin roles=[users, admins]
restheart    | 08:59:44.799 [XNIO-1 task-4] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/bbb from /172.18.0.1:44472 => status=200 elapsed=22ms contentLength=-1 username=admin roles=[users, admins]
restheart    | 08:59:44.843 [XNIO-1 task-5] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/bbb from /172.18.0.1:44480 => status=200 elapsed=7ms contentLength=0 username=admin roles=[users, admins]
restheart    | 08:59:45.062 [XNIO-1 task-2] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/bbb from /172.18.0.1:44488 => status=200 elapsed=9ms contentLength=-1 username=admin roles=[users, admins]
restheart    | 08:59:45.107 [XNIO-1 task-7] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/bbb from /172.18.0.1:44500 => status=404 elapsed=0ms contentLength=104 username=admin roles=[users, admins]
restheart    | 08:59:45.110 [XNIO-1 task-3] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/bbb from /172.18.0.1:44504 => status=404 elapsed=1ms contentLength=104 username=admin roles=[users, admins]
restheart    | 08:59:45.113 [XNIO-1 task-8] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8888/testdb/games/bbb from /172.18.0.1:44496 => status=200 elapsed=8ms contentLength=0 username=admin roles=[users, admins]
restheart    | 08:59:45.360 [XNIO-1 task-1] INFO  o.r.handlers.RequestLoggerHandler - GET http://localhost:8888/testdb/games/bbb from /172.18.0.1:44552 => status=200 elapsed=13ms contentLength=-1 username=admin roles=[users, admins]
ujibang commented 7 years ago

Hi @tunguski,

I thought about it and created the following task in our backlog https://softinstigate.atlassian.net/browse/RH-240

as I wrote, this issue happens because:

and when multiple concurrent write requests are executed against the same document concurrently

The solution proposed in the jira task will address the problem...we are

ps in the log, contentLength comes from exchange.getRequestContentLength(). it is the content length of the request. a GET does not have content at all so it is -1

tunguski commented 7 years ago

Hi @ujibang , Thanks for your response! To be sure - I've reopened this issue because of 404's during GET's where (as I assume) there is no point in time in which document does not exist in db. I totally accept 500 "duplicate document" response - I should not post it in same issue, sorry.

So even as it may be connected to PUT's, I wanted to confirm that this 404's mean working as expected. If I would get 500's only I would treat it as my problem.

Those 404's on GET worry me. Still as I did not experiment with mongo and a few ms intervals before, I can imagine that is totally outside of Resthart scope.

If this is the behaviour that mongo presents without restheart then I'd treat it as a correct result. But if mongo would return document in that case, I'd treat it as a bug.

Having said that I want to emphasize that I don't have enough experience to make any statement. If you'll find it an expected behaviour, feel free to close this issue.

Thanks for all your work!

mkjsix commented 6 years ago

@ujibang can we close this?

ujibang commented 6 years ago

I close this because we have write request serialization in the roadmap. https://softinstigate.atlassian.net/browse/RH-240

also note that mongodb 4.0 is going to introduce Multi-document Transactions (see https://docs.mongodb.com/manual/upcoming/). This will better address this issue.