Is there an easy way to handle dup key error when use out_mongo plugin

[胡展鹏]

When dup key error in mongodb happened, I have to restart the td-agent to work again.

here is the my td-agent log:

2013-12-13 07:31:39 +0900 [warn]: temporarily failed to flush the buffer. next_retry=2013-12-13 07:30:27 +0900 error_class="Mongo::OperationFailure" error="16460: error inserting 1 documents to shard rs1:shard1/xx:27020 at version 326|351||52394cc53b3817ecb1e07c15 :: caused by :: could not get last error from a shard shard1/xx :: caused by :: DBClientBase::findN: transport error: xx ns: admin.$cmd query: { getLastError: 1 }" instance=23456316641420

2013-12-13 07:31:39 +0900 [warn]: temporarily failed to flush the buffer. next_retry=2013-12-13 07:30:29 +0900 error_class="Mongo::OperationFailure" error="16460: error inserting 23 documents to shard rs2:shard2/xx at version 326|351||52394cc53b3817ecb1e07c15 :: caused by :: E11000 duplicate key error index: kome.actionlog.$_id_  dup key: { : \"5426d722-4dee-47c9-9ee2-d172cbb9a1bd\" }" instance=23456316641420

2013-12-13 07:31:39 +0900 [warn]: temporarily failed to flush the buffer. next_retry=2013-12-13 07:30:33 +0900 error_class="Mongo::OperationFailure" error="16460: error inserting 23 documents to shard rs2:shard2/xx at version 326|351||52394cc53b3817ecb1e07c15 :: caused by :: E11000 duplicate key error index: kome.actionlog.$_id_  dup key: { : \"5426d722-4dee-47c9-9ee2-d172cbb9a1bd\" }" instance=23456316641420

[Masahiro Nakagawa]

Hi,

This seems very difficult situation.

1. your mongo shard cluster failed to insert one document to one shard.

2. MongoDB doesn't have a transaction, so mongo shard becomes inconsistent state.

3. according to 1, mongos returns an error

4. mongo client raises an exception and fluentd retries to flush the buffer.

5. $_id_ seems to have unique index, so mongo always raises an exception.

This is a trade-off of NoSQL which doesn't have a transaction.

One possible solution is putting <secondary> in mongo <match> section.

--
You received this message because you are subscribed to the Google Groups "Fluentd Google Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Masahiro Nakagawa]

Ah, wait.

> I have to restart the td-agent to work again.

This is strange. How to generate _id_ value?

Could you paste your configuration here?

[胡展鹏]

This is a trade-off of NoSQL which doesn't have a transaction.
One possible solution is putting <secondary> in mongo <match> section.

Thanks for your advice.

but 

1: does mongo plugin support <secondary>?

2: if mongo shard becomes inconsistent state. I don't think <secondary> can help, because it does not change the buffer data, the data we want to insert into mongodb

在 2013年12月17日星期二UTC+8上午1时59分21秒，repeatedly写道：

[胡展鹏]

here, we did not let mongo to automatically create the _id for us, we use python's uuid4 to generate it(of course, it is not the uuid conflict to cause this error).

BTW, while dup key error happened, we can find that mongo was unstable at the same time.

==========================================================================================

Fri Dec 13 07:31:20.309 [ReplicaSetMonitorWatcher] Socket recv() timeout  xxx:27020

Fri Dec 13 07:31:20.343 [ReplicaSetMonitorWatcher] SocketException: remote: xxx:27020 error: 9001 socket exception [3] server [xxx:27020]

Fri Dec 13 07:31:20.343 [ReplicaSetMonitorWatcher] DBClientCursor::init call() failed

Fri Dec 13 07:31:20.415 [ReplicaSetMonitorWatcher] Detected bad connection created at 1384144984486429 microSec, clearing pool for secondary01:27020

Fri Dec 13 07:31:25.417 [ReplicaSetMonitorWatcher] Socket recv() timeout xxx:27020

Fri Dec 13 07:31:25.417 [ReplicaSetMonitorWatcher] SocketException: remote: xxxx:27020 error: 9001 socket exception [3] server [xxx:27020]

Fri Dec 13 07:31:25.417 [ReplicaSetMonitorWatcher] DBClientCursor::init call() failed

Fri Dec 13 07:31:25.417 [ReplicaSetMonitorWatcher] Detected bad connection created at 1384144994710783 microSec, clearing pool for secondary02:27020

Fri Dec 13 07:31:39.544 [conn330291] warning: could not get last error from a shard shard1/xxx :: caused by :: DBClientBase::findN: transport error: xxx:27020 ns: admin.$cmd query: { getLastError: 1 }

Fri Dec 13 07:31:39.557 [conn330291] warning: exception during insert :: caused by :: 16460 error inserting 1 documents to shard rs1:shard1/xxxx at version 326|351||52394cc53b3817ecb1e07c15 :: caused by :: could not get last error from a shard shard1xxxx :: caused by :: DBClientBase::findN: transport error: config01.mongodb.kk.cn.gu3.jp:27020 ns: admin.$cmd query: { getLastError: 1 }

Fri Dec 13 07:31:41.722 [ReplicaSetMonitorWatcher] warning: No primary detected for set shard1

....

Fri Dec 13 07:32:15.776 [ReplicaSetMonitorWatcher] Primary for replica set shard1 changed to primary01:27020     <==  this server was the original primary server, actually it did not changed but just unavaliable for a while.

==========

在 2013年12月17日星期二UTC+8上午2时38分25秒，repeatedly写道：

[胡展鹏]

This situation we have come across several times is really really troublesome!  

because when it happened, all the following insert will be buffered until the size of buffer exceeded. then all the following inserts will be lost except we can restart the td-agent ASAP.

Now the problem is that how can I get ride of inserted documents from the buffer to avoid dup key error and let the left uninserted documents to be retry again? 

Is it possible to do that? may the I should change the behavior of rescue here https://github.com/fluent/fluent-plugin-mongo/blob/master/lib/fluent/plugin/out_mongo.rb#L119

BTW, according to https://gist.github.com/frsyuki/2656562

"Currently, Fluentd guarantees at-most-once in order to avoid duplicating log entries. The downside is log data may get lost if servers have problems."

Currentyl, How Fluentd guarantees at-most-once in order to avoid duplicating log entries? maybe it also the key to solve my problem

在 2013年12月17日星期二UTC+8上午1时59分21秒，repeatedly写道：

[Masahiro Nakagawa]

> Is it possible to do that?

Maybe possible but general approach is very difficult because MongoDB returns several error types.

Yes, to implemet own mongodb plugin using out_mongo is one approach.

Current situation is mongodb's sharding problem, not mongo client or limitation.

MongoDB can't recover these unstable cluster from client side automatically.

Using <secondary>, fluentd stores such events into file or other resource.

In this approach, you can recover broken events using own script.

My acquaintance who manages over 100 mongod cluster uses same approach to recover the state.

> Currentyl, How Fluentd guarantees at-most-once in order to avoid duplicating log entries?

It depends on each plugin. Other log collector too because

log collector can't know application requirement and actual log limitation.

I think transactional database with unique index is usable for log storage

but non-transactional database with unique index is not good.

If you want to use mongodb in log storage, removing unique index is better

and resolving duplicate problem at query phase.

[胡展鹏]

My acquaintance who manages over 100 mongod cluster uses same approach to recover the state.

yes，we also use the similar approach to recover the lost data, we have another forward to s3 to backup all log data

If you want to use mongodb in log storage, removing unique index is better
and resolving duplicate problem at query phase.

Yes, I cannot agree more with you! it is the design problem, I think that log storage should never refuse any inserts whatever it were

but for our case, now we can not remove the unique index from _id field, right?

 

在 2013年12月17日星期二UTC+8下午12时33分14秒，repeatedly写道：

[Masahiro Nakagawa]

> now we can not remove the unique index from _id field, right?

Error ocurred in '_id_' filed not '_id', right?

[胡展鹏]

Error ocurred in '_id_' filed not '_id', right?

it is the same, I mean the mongodb's default field '_id'。we hava one field '_id' in our every log

E11000 duplicate key error index: kome.actionlog.$_id_  dup key: { : \"5426d722-4dee-47c9-9ee2-d172cbb9a1bd\" }" instance=23456316641420

use kome

db.system.indexes.find()

{

    "v" : 1,

    "key" : {

        "_id" : 1

    },

    "ns" : "kome.actionlog",

    "name" : "_id_"

}

在 2013年12月17日星期二UTC+8下午1时10分29秒，repeatedly写道：

[胡展鹏]

When I try to repeated the dup key case. I noticed that something confused.

I modified some the mongo plugin like this:

============================================================

def operate(collection, records)

      begin

        record_ids, error_records = collection.insert(records, INSERT_ARGUMENT)

        if !@ignore_invalid_record and error_records.size > 0

          operate_invalid_records(collection, error_records)

        end

      rescue Mongo::OperationFailure => e

        # Probably, all records of _records_ are broken...

        message = e.to_s

        if e.error_code == 13066  # 13066 means "Message contains no documents"

          operate_invalid_records(collection, records) unless @ignore_invalid_record

        elsif message.include?('E11000')

          $log.fatal "DUP KEY ERROR: #{e}"

          begin

            error_collection = get_or_create_collection('DUP_KEY')

            error_collection.insert(records, INSERT_ARGUMENT)

          rescue Mongo::OperationFailure => e

            $log.fatal "DUP KEY ERROR TWO TIMES: #{e}"

          end

        else

          raise e

        end

      end

      records

    end

============================================================

we get the following log:

2013-12-17 16:36:48 +0900 [fatal]: DUP KEY ERROR: 16460: error inserting 1 documents to shard rs2:shard2/xxx at version 326|443||52394cc53b3817ecb1e07c15 :: caused by :: E11000 duplicate key error index: kome.actionlog.$_id_  dup key: { : "d82664d2-d3d7-4448-9e85-b165e5a6c35a" }

2013-12-17 16:37:35 +0900 [fatal]: DUP KEY ERROR: 16460: error inserting 59 documents to shard rs2:shard2/xxx at version 326|443||52394cc53b3817ecb1e07c15 :: caused by :: E11000 duplicate key error index: kome.actionlog.$_id_  dup key: { : "0ca0c0b3-6ebb-4162-bfe5-5c0bc57ff87c" }

2013-12-17 16:37:40 +0900 [fatal]: DUP KEY ERROR: 16460: error inserting 13 documents to shard rs2:shard2/xxx at version 326|443||52394cc53b3817ecb1e07c15 :: caused by :: E11000 duplicate key error index: kome.actionlog.$_id_  dup key: { : "95ae8303-8dd9-4bee-be57-51e1d3f9671f" }

In fact, we inserted 52421 documents into 'DUP_KEY' collection. but from the log, we get insert errors only when inserting 1 + 59 + 13 documents.
it means that we can not count on the num of error inserted documents in log? Am I right?

[Masahiro Nakagawa]

> it means that we can not count on the num of error inserted documents in log? Am I right?

I'm not sure. This problem seems mongodb and client error handling issue.

And I don't know the your total documents, so I couldn't judge...

BTW, why do you have same _id_ in several logs?

Does your application sometimes generate same UUID in different record?

--

[Masahiro Nakagawa]

> it is the same, I mean the mongodb's default field '_id'。we hava one field '_id' in our every log

Ah, okay... I confused because '_id' of your record has different format of mongodb's ObjectID.

[胡展鹏]

I'm not sure. This problem seems mongodb and client error handling issue.
And I don't know the your total documents, so I couldn't judge...

we intentionally send 52421 documents into mongodb which we have inserted before,

finally, we got 52421 documents in 'DUP_KEY' collection, it is correct.

but from the log, we can not got the right message about 52421 dup key documents, so we think there are something wrong with error handling.

BTW, why do you have same _id_ in several logs?
Does your application sometimes generate same UUID in different record?

yes, our application should generates uuid for every log record to satisfy our special needs, 

so we use the '_id' field to replace the mongodb's default '_id' to save storage space 

although from now it seems not a good idea to do that because it leads to dup key problems.

在 2013年12月18日星期三UTC+8上午3时08分22秒，repeatedly写道：

[胡展鹏]

Does your application sometimes generate same UUID in different record?

we don't think our application sometimes generate same UUID in different record, 

because we check the record inserted and the dup key error record, they were totally the same record, not just the _id filed. 

在 2013年12月18日星期三UTC+8上午10时21分30秒，胡展鹏写道：

[Masahiro Nakagawa]

> so we think there are something wrong with error handling.

Your code is simply, catching an exception and dump error message.

If these are different from actual result, mongos or mongo client may have a bug.

[Tom Maiaroto]

I know this is an older thread, but I'm in the same boat.

I intentionally put a unique index on a field (not _id -- I'm using regular ObjectIds) because I knew Mongo would not store the duplicate.

I wanted it to not store the duplicate. So I intentionally used the error...Which has worked for me before in the past in other circumstances (not using fluentd).

 

Is there just any way to not retry?

That, to me, seems like the easiest solution. If there's a dupe, I know I have the record...I just need Fluentd plugin to stop trying to insert.

Don't get me wrong, it's really awesome that there's a retry in case there should be a network problem...But being able to configure it so that it just doesn't retry and ignores the error would be great.

Any new ideas on this issue?

[Masahiro Nakagawa]

Generally, unique feature should not be used in storing logs and

use GroupBy or similar feature instead.

MongoDB, Treasure Data, Redshift, BigQuery and other non RDBMS database

doesn't have actual transaction.

So if MongoDB returns duplicated error, Fluentd / application side hard to recover

the status. How many documents are imported or failed?

And MongoDB client doesn't return parsable error message so

recovering unique error is toooo hard.

Maybe, we can implement but it causes performance degression

and MongoDB internal dependent code makes code complex.

I recommend non-unique idenx with groupby.

--

You received this message because you are subscribed to the Google Groups "Fluentd Google Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fluentd+u...@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Tom Maiaroto]

hmm, there's the potential for a lot of dupes. 

the thing is i'm working on a social media analytics platform...and here's the setup:

a user can create multiple "territories" or sets of criteria to monitor/search for. ie. "world cup" and say "fifa video game"

this system goes out and searches keywords, follows accounts, etc. it will store bits of processed information from twitter status updates, etc.

there's a potential for dupes in a few places.

A. several keywords in the same territory could return the same status updates

B. several sets of criteria can return the same messages (but that's ok, i actually want to store the duplicate message in this case because i'll flag it as belonging to a different set)

C. while i tell the API to start from a specific time or message id, sometimes dupes come in.

so i really do need to ignore duplicate data. when a user gets to specify search criteria, there's no real way to know exactly what's going to happen. they could enter in the same exact keywords to search on for all i know. 

i want to make the system as efficient and fool proof as possible...so ignoring duplicates is one great way of solving these issues.

i'm re-building this platform and was not using fluentd before. and before the mass import into mongodb wasn't problematic at all. dupes were ignored. this was done with a file that contained JSON objects line by line using mongo import from the command line. in fact, the same file i'm logging to that then gets processed through fluentd would work with mongo import.

so mongodb's tools seem to be able to cope with this... i was hoping fluentd could as well.

i don't need to use mongodb of course, but i don't want to say mongodb "can't" do this or isn't sufficient, because it definitely was fine for me in the past. i just don't think it's not fair to blame the database in this case and i'm hoping there's a clever solution.

[Tom Maiaroto]

...and the other part of this is because i worry about performance with a groupby and all the potential dupes.

[Masahiro Nakagawa]

I see. I understood the situation.

In your case, the use of mongodb is tied into your application requirement.

>  line by line using mongo import

Yes, it is easy to handle duplicated error but out_mongo uses different approach.

out_mongo imports events with batch mode and it is a retry unit.

This increases the throughput and makes a retry reliable.

I got the PR for this issue but I rollbacked the commit.

See this PR:

- https://github.com/fluent/fluent-plugin-mongo/pull/26

- https://github.com/fluent/fluent-plugin-mongo/pull/27

If mongodb supports 'ignore duplicated document' like option,

this problem will be resolved easily.

For resolving the problem temporary, how about using out_exec with your script?

<match mongo.**>

  type exec

  format json

  command /path/to/ruby /path/to/your/script

  # other options

</match>

In this approach, you can re-use your script.

[Tom Maiaroto]

oh cool! yea, i can then exec the import like i used to. that's cool.

and mongodb isn't so much a requirement as it is an option i'd like people to have. i'm working on an open source social media analytics platform (http://www.socialharvest.io) that should be flexible enough to allow users to use whichever database they want (via fluentd). that said... if mongo users (and i like mongo, i might use it myself) want to use mongo and need to use the out_exec instead... that's fine.

i'm porting / re-building something that used mongodb before with great success and so that's just my starting point.