Re: [mongodb-user] Writeback error

[lagha imen]

Dear Mr Patrick Peschlow

I would like to know if there is any graphical representation that defines a model adapted to a NoSQL DataBase based on document like the Conceptual Data Model for exemple. 

The problem is that I can not find a way to represent my collections and documents clearly so that I can make a good conception for my project.

I'm thankfull to your help 

 

yours Imen Lagha 

2012/10/17 Patrick Peschlow <patrick....@codecentric.de>

Dear MongoDB users,

once in a while our application, using the Java client 2.9.1, faces periods where 'writeback' errors occur. During these periods, the errors seem to happen randomly when inserting/updating collection entries.

When running on Mongo 2.0.7, the error manifested in exceptions like this (with the client being stuck for 100 seconds before receiving the error):

com.mongodb.CommandResult$CommandFailure: command failed [getlasterror]: { "serverUsed" : "/127.0.0.1:27017" , "assertion" : "didn't get writeback for: 506d8b3bf69471a8f63db248 after: 101179 ms" , "assertionCode" : 13403 , "errmsg" : "db assertion failure" , "ok" : 0}

We discovered the ticket https://jira.mongodb.org/browse/SERVER-6540 which looked like a possible explanation for the problem. Thus we upgraded to Mongo 2.2.1 RC0. However, after a couple of days the same (?) problem occurred. Now the exception looks like this (here, we made an update request using WriteConcern.SAFE):

com.mongodb.MongoException: writeback
    at com.mongodb.CommandResult.getException(CommandResult.java:100) ~[mongo-java-driver-2.9.1.jar:na]
    at com.mongodb.CommandResult.throwOnError(CommandResult.java:134) ~[mongo-java-driver-2.9.1.jar:na]
    at com.mongodb.DBTCPConnector._checkWriteError(DBTCPConnector.java:142) ~[mongo-java-driver-2.9.1.jar:na]
    at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:183) ~[mongo-java-driver-2.9.1.jar:na]
    at com.mongodb.DBTCPConnector.say(DBTCPConnector.java:155) ~[mongo-java-driver-2.9.1.jar:na]
    at com.mongodb.DBApiLayer$MyCollection.update(DBApiLayer.java:328) ~[mongo-java-driver-2.9.1.jar:na]
    at com.mongodb.DBCollection.update(DBCollection.java:160) ~[mongo-java-driver-2.9.1.jar:na]

Just to mention, we also had the writeback error (including the 100 second wait) once on the mongo shell.

We have a pretty standard setup, almost like in the textbook examples: Two replica sets A and B with three members each, and each replica set is used as a shard. The system is running on four hosts, with the mongo processes distributed as follows:

- Host 1: one mongod for A, one mongod for B, one config server, and one mongos
- Host 2: one mongod for A, one mongod for B, one config server, and one mongos
- Host 3: one mongod for A, one mongod for B, one config server, and one mongos
- Host 4: one mongos

Each of the mongos knows all three config servers. Our application connects to the local mongos on the respective host.

When the 'writeback' problem happens, it usually only affects one mongos (once we observed that two mongos were affected). According to rs.status() the replica sets are fine. Restarting the affected mongos is a reliable way to quickfix the problem (it doesn't continue to have 'writeback' errors after restart) but of course it is not the solution we are looking for. So we are a bit at a loss as to what might be causing this problem. Especially because we have almost no load on the system.

Apart from the exceptions, the only thing we could find are messages like this in the mongos logs. They occur every couple of minutes in all mongos logs, all the time (not just the logs of the mongos affected by the 'writeback' problem):

Wed Oct 17 10:51:43 [Balancer] warning: distributed lock 'balancer/node01:27017:1350302113:1804289383 did not propagate properly. :: caused by :: 8017 update not consistent  ns: config.locks query: { _id: "balancer", state: 0, ts: ObjectId('507e719b030ba045fdad8ec8') } update: { $set: { state: 1, who: "node01:27017:1350302113:1804289383:Balancer:846930886", process: "node01:27017:1350302113:1804289383", when: new Date(1350463903046), why: "doing balance round", ts: ObjectId('507e719fc38a581b686df2f6') } } gle1: { updatedExisting: true, n: 1, connectionId: 61, waited: 14, err: null, ok: 1.0 } gle2: { updatedExisting: false, n: 0, connectionId: 110, waited: 35, err: null, ok: 1.0 }

We are unsure as to whether these messages are problematic and whether they are connected to our problem.

It would be great if someone could help us - or at least enlighten us what might be going on here.

Best regards,
Patrick

--
You received this message because you are subscribed to the Google
Groups "mongodb-user" group.
To post to this group, send email to mongod...@googlegroups.com
To unsubscribe from this group, send email to
mongodb-user...@googlegroups.com
See also the IRC channel -- freenode.net#mongodb

[Jeremy Mikola]

On Wednesday, October 17, 2012 5:48:01 PM UTC-4, lagha imen wrote:

Dear Mr Patrick Peschlow

I would like to know if there is any graphical representation that defines a model adapted to a NoSQL DataBase based on document like the Conceptual Data Model for exemple. 

The problem is that I can not find a way to represent my collections and documents clearly so that I can make a good conception for my project.

I'm thankfull to your help 

Iagha,

I think this article might prove helpful for you: http://highlyscalable.wordpress.com/2012/03/01/nosql-data-modeling-techniques/.

In the future, please create a new mailing list thread if your topic is unrelated to the discussion. That will ensure you get more visibility for the question as well as keep the thread on-topic.

[Jeremy Mikola]

On Wednesday, October 17, 2012 8:18:57 AM UTC-4, Patrick Peschlow wrote:

Apart from the exceptions, the only thing we could find are messages like this in the mongos logs. They occur every couple of minutes in all mongos logs, all the time (not just the logs of the mongos affected by the 'writeback' problem):

Patrick,

Are there any WriteBackListener errors in the mongos logs, or is the Balancer warning the only line of interest? In particular, is there anything in the logs that you can match up with the CommandResult or MongoException errors from the Java application?

Given that the Balancer warnings are repeating fairly frequently, is there anything to suggest they're happening around the same time as the Java exceptions?

[Patrick Peschlow]

Hi Jeremy,

we also suspected that and checked, however we found no correlation at all between the balancer warnings and the Java exceptions. Note that we still have these balancer warnings even when the writeback errors disappeared after we restarted mongos.

There is no error output at all in the mongos logs, the warnings were the only interesting entries that we could find. Nor could we find any error output in one of the mongod logs.

-Patrick

[Jeremy Mikola]

Patrick,

Perhaps boosting the verbosity of the mongod/mongos processes might help, in case the GLE error is something loggable at a more verbose level.

One possibility that comes to mind is a corruption bug that was present in the 2.9.0 and 2.9.1 releases of the Java driver. If you haven't done so already, I'd suggest updating to the latest version and seeing if the problem can be reproduced. The release announcement is here: https://groups.google.com/d/topic/mongodb-user/kAA7K36QtkQ/discussion

Additionally, it might be helpful to also see if the problem can be reproduced in something other than the Java driver (e.g. Python). If it can, that would hint that there may be a server bug at play, and I would encourage you to open a ticket here: https://jira.mongodb.org/browse/SERVER

Since it seems that the balancer errors in the logs don't correlate with the writeback errors, we may be looking at two distinct issues here (both worth reporting with steps to reproduce).

[Patrick Peschlow]

Jeremy,

thanks a lot for your suggestions. We'll update the log level to a more verbose one and see if we can find anything when the writeback problem occurs the next time (it didn't since I started this thread). We didn't manage to forcibly reproduce it yet, unfortunately.

The Java driver is probably not to blame, as the same problem also happened to us on the Mongo shell once. But thanks for mentioning the driver update with a critical fix that we'd otherwise have missed.

I'm also pretty sure the balancer problem is a different one (it still happens all the time). Will try to find some way of reproducing or affecting the behavior and then create JIRA tickets, as you suggest.

Thanks again,
Patrick

[Wojons Tech]

Hello,

I wanted to share that i am also getting a an intresting error in my logs.

"writeback:com.mongodb.CommandResult.getException(CommandResult.java:100),com.mongodb.CommandResult.throwOnError(CommandResult.java:134),com.mongodb.DBTCPConnector._checkWriteError(DBTCPConnector.java:142),com.mongodb.DBTCPConnector.say(DBTCPConnector.java:183),com.mongodb.DBTCPConnector.say(DBTCPConnector.java:155)

pretty much we have an IOS game, the data loads fine user starts to play and then when the client goes to save the game we get an error pretty much we check to see the number of documents that were updated is 1 and we dont get a 1 back, but if u check the database the new data is there.

[Jeremy Mikola]

On Saturday, October 27, 2012 4:57:49 PM UTC-4, Wojons Tech wrote:

Hello,

I wanted to share that i am also getting a an intresting error in my logs.

"writeback:com.mongodb.CommandResult.getException(CommandResult.java:100),com.mongodb.CommandResult.throwOnError(CommandResult.java:134),com.mongodb.DBTCPConnector._checkWriteError(DBTCPConnector.java:142),com.mongodb.DBTCPConnector.say(DBTCPConnector.java:183),com.mongodb.DBTCPConnector.say(DBTCPConnector.java:155)

pretty much we have an IOS game, the data loads fine user starts to play and then when the client goes to save the game we get an error pretty much we check to see the number of documents that were updated is 1 and we dont get a 1 back, but if u check the database the new data is there.

Were you using a write concern for the original update? Without it, the driver would likely not report that any documents were updated, since getLastError status is not included in the update response. A write concern of 1 would ensure that the primary server acknowledged the write operation and give you the "1" that you're expecting (or an error if one occurred). Either way, you'd likely still find the data present when you inspect the database.