Creation of collection not synchronized

christiangroth commented 6 years ago

We have a quite simple approach putting new content to mongo via restheart:

Try to put the document using PUT /dbname/collectionname/document
if we get a HTTP 404 response then know that the database and / or collections needs to be created so we check their existence using GET /dbname and GET /dbname/collectionname and create them using PUT request if needed.
As our content generation runs in parallel got into the situation where multiple threads / clients tried to PUT /dbfoo/collectionbar/1, PUT /dbfoo/collectionbar/2, PUT /dbfoo/collectionbar/3, ...
Each of them recognizing the DB and / or collection needs to be created and as a result of this multiple PUT /dbfoo/collectionbar are sent to restheart in parallel

Expected Behavior

requests creating a collection (and maybe also a db) are synchronized so no request will fail due to concurrency issues

Current Behavior

The request creating the collection was answered with HTTP 201, that's fine
Other requests were answered with HTTP 200, because the collection was created in the meantime
Zero or one request was answered with HTTP 500
unfortunately we do not have any more logs / information, there is no error logged, etc.

Context / Environment

restheart 3.3.1

ujibang commented 6 years ago

Hi @christiangroth,

all write requests in RESTHeart have upsert semantic. So the first PUT /db/collection actually creates the collection (201 Created). The other ones update it (200 Ok).

Note that with RESTHeart db and collections have properties (see https://restheart.org/learn/representation-format/) so yes, you can update the properties of a collection with a PUT.

If you want to avoid updating them, you can use the ETag.

An example with httpie

$ http PUT :8080/db/test2?checkEtag
HTTP/1.1 201 Created

$ http PUT :8080/db/test2?checkEtag
HTTP/1.1 409 Conflict

christiangroth commented 6 years ago

Hi,

the ETag hint is a good one, we will think about it. Nevertheless I think the description I provided maybew was not clear enought. The issue we care about is restheart providing HTTP 500 responses in some cases. This does not happen every time, so it seems to be an synchronization issue.

christiangroth commented 6 years ago

Anything new on this one? Any suggestions?

ujibang commented 6 years ago

Hi @christiangroth ,

does ?checkEtag solve the problem?

If not, can you provide a reproducer?

christiangroth commented 6 years ago

Hey @ujibang,

I think we don't get each other right. The whole thing is not about checking the Etag at all, it's about getting HTTP 500 instead of HTTP 200 or HTTP 201. How shpould checking the Etag avoid the HTTP 500 response?

ujibang commented 6 years ago

Checking the ETag forces RESTHart to look at the _etag property of the collection, before actually upserting it. I thought this might avoid the error that leads 500.

Since I'm not able how to reproduce the issue, I'm not sure if this is actually true. I think it is worth a try.

Besides this, can you please share a test case that reproduce the bug?

christiangroth commented 6 years ago

Ah ... now I got it, thanks!m I'll try it later and let you know if that helps. Unfortunately we do not have a testcase, we can just run our application pushing data to restheart and see it happen.

christiangroth commented 6 years ago

Hi @ujibang,

I've added ?checkEtag to the PUT requests creating db and collection, but this did not fix anything. I've attached the restheart logfile. As you can see there are exceptions like "collection ... already exists" and in additon also the HTTP 500 responses.

I would have expected HTTP 409 Conflict responses instead of exceptions or I am worng here?

297_with_etag_check.log

ujibang commented 6 years ago

yes this is a bug indeed and the ?checkEtag trick does not workaround it.

I extracted from the log file, the evidence of two concurrent requests (actually happening at exactly the same millisecond 09:08:01.623), one leading to error 500.

The problem is that RESTHeart checks if a collection exists, and the it creates or updates it. These are two different, not atomic operations that can lead to this exception.

I'm going to handle the exception accordingly.


09:08:01.622 [XNIO-1 task-4] ERROR org.restheart.handlers.ErrorHandler - Error handling the request
com.mongodb.MongoCommandException: Command failed with error 48: 'a collection 'xxx.products' already exists' on server xxx:27017. The full response is { "note" : "the autoIndexId option is deprecated and will be removed in a future release", "ok" : 0.0, "errmsg" : "a collection 'MithrasEnergy20.products' already exists", "code" : 48, "codeName" : "NamespaceExists" }
    at com.mongodb.connection.ProtocolHelper.getCommandFailureException(ProtocolHelper.java:115)
    at com.mongodb.connection.CommandProtocol.execute(CommandProtocol.java:107)
    at com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159)
    at com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:289)
    at com.mongodb.connection.DefaultServerConnection.command(DefaultServerConnection.java:176)
    at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:216)
    at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:207)
    at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:146)
    at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:139)
    at com.mongodb.operation.CreateCollectionOperation$1.call(CreateCollectionOperation.java:380)
    at com.mongodb.operation.CreateCollectionOperation$1.call(CreateCollectionOperation.java:376)
    at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:424)
    at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:415)
    at com.mongodb.operation.CreateCollectionOperation.execute(CreateCollectionOperation.java:376)
    at com.mongodb.operation.CreateCollectionOperation.execute(CreateCollectionOperation.java:53)
    at com.mongodb.Mongo.execute(Mongo.java:819)
    at com.mongodb.Mongo$2.execute(Mongo.java:802)
    at com.mongodb.MongoDatabaseImpl.createCollection(MongoDatabaseImpl.java:198)
    at com.mongodb.MongoDatabaseImpl.createCollection(MongoDatabaseImpl.java:169)
    at org.restheart.db.CollectionDAO.upsertCollection(CollectionDAO.java:331)
    at org.restheart.db.DbsDAO.upsertCollection(DbsDAO.java:460)
    at org.restheart.handlers.collection.PutCollectionHandler.handleRequest(PutCollectionHandler.java:154)
    at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:121)
    at org.restheart.handlers.metadata.TransformersListHandler.handleRequest(TransformersListHandler.java:73)
    at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:121)
    at org.restheart.handlers.metadata.TransformerHandler.handleRequest(TransformerHandler.java:75)
    at org.restheart.handlers.RequestDispatcherHandler.handleRequest(RequestDispatcherHandler.java:562)
    at org.restheart.handlers.injectors.CollectionPropsInjectorHandler.handleRequest(CollectionPropsInjectorHandler.java:107)
    at org.restheart.handlers.PipedHttpHandler.next(PipedHttpHandler.java:121)
    at org.restheart.handlers.injectors.DbPropsInjectorHandler.handleRequest(DbPropsInjectorHandler.java:92)

09:08:01.623 [XNIO-1 task-8] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8080/xxx/products?checkEtag from /172.31.1.1:43774 => status=201 elapsed=23ms contentLength=0

09:08:01.623 [XNIO-1 task-4] INFO  o.r.handlers.RequestLoggerHandler - PUT http://localhost:8080/xxx/products?checkEtag from /172.31.1.1:43782 => status=500 elapsed=23ms contentLength=309

ujibang commented 6 years ago

In commit 71d192c6481311f6c0621b57911bbd707fa529d5, there is a possible fix.

can you please test it?

christiangroth commented 6 years ago

Hi @ujibang,

sorry for the late response, I was out of office for some days. The fix looks good, I will test it and get back to you!

I'm wondering if the same situation can happen when creating a database instead of a collection and if this should also be fixed??

grossmueller-espirit commented 6 years ago

Hi there, with 3.4.2 I was no longer able to reproduce the exception - thank you @ujibang

PS: would be great if you could comment on Christian's last question (whether it may still happen upon db creation even though I did not run into this (so far))

grossmueller-espirit commented 6 years ago

Hello again, unfortunately, we are now encountering 500 Responses when concurent requests for deleting files are sent. I am opening a new question for this....

mkjsix commented 6 years ago

I think this specific issue has been already solved so I'm closing this, if not please re-open.

SoftInstigate / restheart