elasticsearch-river-mongodb configuration problems

Dear Richard:

I am trying to set up elasticsearch-river-mongodb, and I’m baffled. I would be most grateful if you could help me out.

I am trying to use ElasticSearch to enable searching our MongoDB. I configured MongoDB to have one replSet, and I installed and configured elasticsearch-river-mongodb.

I am using the following versions:

MongoDB: 2.4.8 ElasticSearch: 0.90.7 elasticsearch-river-mongodb: 1.7.3

We need to search content in our collection "units". An example unit document follows:

/* 16 */ { "_id" : ObjectId("52ab3738da0602978bf3c872"), "_class" : "com.bulb.learn.domain.units.PublishedPageUnit", "_v" : "0.1.0.0", "publishedDate" : ISODate("2013-12-16T15:59:51.611-07:00"), "draftPageId" : ObjectId("52ab75aeda06658f163446e5"), "contentBlocks" : [ { "_id" : ObjectId("52ab70f5da06b0688dc41742"), "text" : "

JERUSALEM CRICKETS

Facts, Identification & Control

<a href=\"http://www... They can bite, but usually when they are cornered or when they are picked up. The bite can be painful, but there is no venom delivered.

", "_class" : "com.bulb.learn.domain.blocks.TextBlock" }, { "_id" : ObjectId("52ab71eeda06b0688dc4175a"), "caption" : "Hello, Mr. Potato Bug!", "fullImageAsset" : { "$ref" : "assets", "$id" : ObjectId("52ab71efda06b0688dc4175b") }, "scaledImageAsset" : { "$ref" : "assets", "$id" : ObjectId("52ab721fda06b0688dc41761") }, "_class" : "com.bulb.learn.domain.blocks.ImageBlock" } ], "name" : "Potato Bugs On Parade", "description" : "X", "accentIndex" : 4, "migratedImages" : false, "featured" : false, "path" : "potato-bugs-on-parade~1", "ownerId" : ObjectId("52aa4a7eda06e945e81c7874"), "acls" : [ { "accessMap" : { "Role:USER" : { "allow" : [ "READ" ] }, "Account:52aa4a7eda06e945e81c7874" : { "allow" : [ "CREATE", "READ", "UPDATE", "DELETE", "GRANT" ] } }, "sourceClass" : "com.bulb.learn.domain.units.PublishedPageUnit", "sourceId" : ObjectId("52ab3738da0602978bf3c872") } ], "horizontalImage" : { "$ref" : "assets", "$id" : ObjectId("52ab84cada0667218c576b2f") }, "verticalImage" : { "$ref" : "assets", "$id" : ObjectId("52ab84ccda0667218c576b33") } }

Primarily, we want to search the "name" and "description" fields, and the "text" and "caption" fields in the objects in the "contentBlocks" array. We intend to extract ObjectId (as string) from the _source in the returned hits, and load the referenced unit.

I have indexed our "units" collection as follows:

curl -XGET "IP_ADDRESS_HERE:9200/_river/units_river/_meta?pretty=true"

outputs: { "_index" : "_river", "_type" : "units_river", "_id" : "_meta", "_version" : 11, "exists" : true, "_source" : { "type": "mongodb", "mongodb": { "servers": [ { "host": "IP_ADDRESS_HERE", "port": 27017 } ], "options": { "secondary_read_preference": true, "import_all_collections": false, "skip_initial_import": false, "store_statistics": true }, "db": "bulbDev", "collection": "units", "gridfs": false }, "index": { "name": "units_index", "type": "unit" } } }

Immediately after starting up, the log is as follows:

[2013-12-17 08:56:45,287][INFO ][node [2013-12-17 08:57:55,005][INFO ][node [2013-12-17 08:57:55,005][INFO ][node [2013-12-17 08:57:55,080][INFO ][plugins [2013-12-17 08:57:57,081][TRACE][rest.action.mongodb [2013-12-17 08:57:57,164][INFO ][node [2013-12-17 08:57:57,164][INFO ][node [2013-12-17 08:57:57,252][INFO ][transport [2013-12-17 08:58:00,316][INFO ][cluster.service [2013-12-17 08:58:00,347][INFO ][discovery [2013-12-17 08:58:00,362][INFO ][http [2013-12-17 08:58:00,363][INFO ][node [2013-12-17 08:58:00,839][INFO ][gateway [2013-12-17 08:58:00,921][TRACE][org.elast [2013-12-17 08:58:00,922][INFO ][river.mongodb [2013-12-17 08:58:00,925][TRACE][river.mongodb [2013-12-17 08:58:00,925][INFO ][river.mongodb [2013-12-17 08:58:00,940][TRACE][river.mongodb [2013-12-17 08:58:00,941][INFO ][org.elast [2013-12-17 08:58:00,943][DEBUG][river.mongodb.util [2013-12-17 08:58:00,978][DEBUG][org.elast [2013-12-17 08:58:00,979][INFO ][org.elast [2013-12-17 08:58:00,979][INFO ][org.elast [2013-12-17 08:58:01,024][INFO ][org.elast ] [Devil's Sooty Brother] stopping ... ] [Devil's Sooty Brother] version[0.90.7], pid[18720], build[36897d0/2013-11-13T12:06:54Z] ] [Devil's Sooty Brother] initializing ... ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb ] [Devil's Sooty Brother] initialized ] [Devil's Sooty Brother] starting ... ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][inUpU_1URTy__bn72XZ59A][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) ] [Devil's Sooty Brother] Zaragossa/inUpU_1URTy__bn72XZ59A ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} ] [Devil's Sooty Brother] started ] [Devil's Sooty Brother] recovered [2] indices into cluster_state icsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] ] Parse river settings for units_river ] mongoServersSettings: [{port=27017, host=127.0.0.0}] ] Server: 127.0.0.0 - 27017 ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} icsearch.river.mongodb.MongoDBRiver] Starting river units_river ] setRiverStatus called with units_river - RUNNING icsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] icsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.3] - hash[4ca377f] - time[2013-12-05T14:34:13Z] icsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] icsearch.river.mongodb.MongoDBRiver] MongoAdminUser: - isAuthenticated: false

I have not configured any explicit mapping for the "unit" type. The reported mapping is as follows:

curl -XGET "IP_ADDRESS_HERE:9200/_mapping?pretty=true"

{ "_river" : { "units_river" : { "properties" : { "index" : { "properties" : { "name" : { "type" : "string" }, "type" : { "type" : "string" } } }, "mongodb" : { "properties" : { "collection" : { "type" : "string" }, "db" : { "type" : "string" }, "gridfs" : { "type" : "boolean" }, "options" : { "properties" : { "import_all_collections" : { "type" : "boolean" }, "secondary_read_preference" : { "type" : "boolean" }, "skip_initial_import" : { "type" : "boolean" }, "store_statistics" : { "type" : "boolean" } } }, "servers" : { "properties" : { "host" : { "type" : "string" }, "port" : { "type" : "long" } } }, "status" : { "type" : "string" } } }, "type" : { "type" : "string" } } } }, "units_index" : { } }

Note that there is a mapping for "units_index", but it is empty.

If I search, no results are returned:

curl -XGET IP_ADDRESS_HERE:9200/_search/?q=potato&pretty=true { "took" : 13, "timed_out" : false, "_shards" : { "total" : 2, "successful" : 2, "failed" : 0 }, "hits" : { "total" : 0, "max_score" : null, "hits" : [ ] } }

No errors appear in the log after this search.

Is my system correctly configured? Why are there no search results found? What's wrong?

Thanks, David Haimson

David,

Can you please try the following:

Delete the river and units_index index?
Stop ES
Delete log file
Restart ES
Create the river
Provide the full ES log file.

Thanks, Richard.

Richard:

I did:

Delete river:

curl -XDELETE http://IP_ADDRESS_HERE92.168.107.228:9200/_river/units_river

{"ok":true,"acknowledged":true}

Delete units_index:

curl -XDELETE http://IP_ADDRESS_HERE:9200/units_index

{"ok":true,"acknowledged":true}

Killed ElasticSearch.

Deleted log.

Restarted ElasticSearch.

Recreated the river:

Before:

curl -XGET "IP_ADDRESS_HERE:9200/_river/units_river/_meta?pretty=true" { "_index" : "_river", "_type" : "units_river", "_id" : "_meta", "exists" : false }

{ "ok" : true, "_index" : "_river", "_type" : "units_river", "_id" : "_meta", "_version" : 1 }

After:

curl -XGET "IP_ADDRESS_HERE:9200/_river/units_river/_meta?pretty=true" { "_index" : "_river", "_type" : "units_river", "_id" : "_meta", "_version" : 1, "exists" : true, "_source" : { "type": "mongodb", "mongodb": { "servers": [ { "host": "127.0.0.0", "port": 27017 } ], "options": { "secondary_read_preference": true, "import_all_collections": false, "skip_initial_import": false, "store_statistics": true }, "db": "bulbDev", "collection": "units", "gridfs": false }, "index": { "name": "units_index", "type": "unit" } } }

The log:

[2013-12-17 11:17:04,823][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[22619], build[36897d0/2013-11-13T12:06:54Z] [2013-12-17 11:17:04,824][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-17 11:17:04,855][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-17 11:17:06,423][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-17 11:17:06,484][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-17 11:17:06,484][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-17 11:17:06,552][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2013-12-17 11:17:09,607][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][wPrTMGKGSjG9Godr9vbUvg][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-17 11:17:09,641][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/wPrTMGKGSjG9Godr9vbUvg [2013-12-17 11:17:09,652][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2013-12-17 11:17:09,652][INFO ][node ] [Devil's Sooty Brother] started [2013-12-17 11:17:09,928][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2013-12-17 11:17:12,729][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-17 11:17:12,735][INFO ][river.routing ] [Devil's Sooty Brother] no river _meta document found, retrying in 1000 ms [2013-12-17 11:17:13,753][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2013-12-17 11:17:13,754][INFO ][river.mongodb ] Parse river settings for units_river [2013-12-17 11:17:13,756][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-17 11:17:13,756][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017 [2013-12-17 11:17:13,767][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2013-12-17 11:17:13,769][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2013-12-17 11:17:13,770][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2013-12-17 11:17:13,776][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] [2013-12-17 11:17:13,777][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-17 11:17:13,778][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.3] - hash[4ca377f] - time[2013-12-05T14:34:13Z] [2013-12-17 11:17:13,778][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2013-12-17 11:17:13,816][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2013-12-17 11:17:13,892][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: - isAuthenticated: false

Thanks, David Haimson

The next line in the log should display MongoDB version. It looks like the river cannot access the admin database. Maybe authentication issue or connection to MongoDB.

Hmmm. On our development boxes, we run MongoDB unauthenticated. In this case, there is no admin database at all. I’m not setting the credentials field in the river config.

It appears that in this case the code (https://github.com/richardwilly98/elasticsearch-river-mongodb/blob/master/src/main/java/org/elasticsearch/river/mongodb/MongoDBRiver.java) sets adminDb to null, and logging the MongoDB version doesn’t happen. Does that keep the oplog tailing from happening?

I will try setting up authentication and see if that fixes it. Is unauthenticated MongoDB is not a supported configuration?

Thanks, David Haimson

Hi David,

The river also works fine when authentication is turned off.

You are sure mongodb is on port=27017, host=127.0.0.0 ? Is the ip address correct? Thanks, Richard.

Yes, 127.0.0.0:27017 is right.

I set up authentication on the MongoDB, and added credentials to my setup script. Now the log looks like this:

[2013-12-17 15:51:16,451][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[27320], build[36897d0/2013-11-13T12:06:54Z] [2013-12-17 15:51:16,451][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-17 15:51:16,482][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-17 15:51:18,030][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-17 15:51:18,093][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-17 15:51:18,093][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-17 15:51:18,161][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2013-12-17 15:51:21,210][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][IqUMl8SGSvubd3PiV1uMBg][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-17 15:51:21,245][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/IqUMl8SGSvubd3PiV1uMBg [2013-12-17 15:51:21,257][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2013-12-17 15:51:21,257][INFO ][node ] [Devil's Sooty Brother] started [2013-12-17 15:51:21,536][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state /usr/local/elasticsearch$ cat logs/Zaragossa.log [2013-12-17 15:51:16,451][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[27320], build[36897d0/2013-11-13T12:06:54Z] [2013-12-17 15:51:16,451][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-17 15:51:16,482][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-17 15:51:18,030][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-17 15:51:18,093][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-17 15:51:18,093][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-17 15:51:18,161][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2013-12-17 15:51:21,210][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][IqUMl8SGSvubd3PiV1uMBg][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-17 15:51:21,245][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/IqUMl8SGSvubd3PiV1uMBg [2013-12-17 15:51:21,257][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2013-12-17 15:51:21,257][INFO ][node ] [Devil's Sooty Brother] started [2013-12-17 15:51:21,536][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2013-12-17 15:54:39,653][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-17 15:54:39,660][INFO ][river.routing ] [Devil's Sooty Brother] no river _meta document found, retrying in 1000 ms [2013-12-17 15:54:40,682][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2013-12-17 15:54:40,683][INFO ][river.mongodb ] Parse river settings for units_river [2013-12-17 15:54:40,689][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-17 15:54:40,689][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017 [2013-12-17 15:54:40,705][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2013-12-17 15:54:40,706][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2013-12-17 15:54:40,707][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2013-12-17 15:54:40,713][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] [2013-12-17 15:54:40,714][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.3] - hash[4ca377f] - time[2013-12-05T14:34:13Z] [2013-12-17 15:54:40,714][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2013-12-17 15:54:40,714][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-17 15:54:40,749][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2013-12-17 15:54:40,840][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: admin - isAuthenticated: false [2013-12-17 15:54:40,840][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with admin

Search still fails. “match_all” returns:

curl -XGET IP_ADDRESS_HERE:9200/_all/_search/?pretty=true -d ' { "query" : { "match_all" : {} } } ' { "took" : 1, "timed_out" : false, "_shards" : { "total" : 2, "successful" : 2, "failed" : 0 }, "hits" : { "total" : 2, "max_score" : 1.0, "hits" : [ { "_index" : "_river", "_type" : "units_river", "_id" : "_meta", "_score" : 1.0, "_source" : { "type": "mongodb", "mongodb": { "servers": [ { "host": "127.0.0.0", "port": 27017 } ], "options": { "secondary_read_preference": true, "import_all_collections": false, "skip_initial_import": false, "store_statistics": true }, "credentials": [ { "db": "local", "user": "user", "password": "user" }, { "db": "admin", "user": "admin", "password": "admin" } ], "db": "bulbDev", "collection": "units", "gridfs": false }, "index": { "name": "units_index", "type": "unit" } } }, { "_index" : "_river", "_type" : "units_river", "_id" : "_riverstatus", "_score" : 1.0, "_source" : {"mongodb":{"status":"RUNNING"}} } ] } }

What next?

Thanks, David Haimson

For some reason the river is not able to connect to MongoDB.

It looks like a configuration / environment issue (firewall, anti-virus?).

Can you run rs.status() from Mongo shell and send the result.

As long as you do not see a line like: [INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB version - 2.4.8 Something is not correctly setup.

Thanks, Richard.

All the components are local. As far as I know, no firewall is involved. I’m on a Macintosh, and I’m not aware of any anti-virus software running.

Here is the output from rs.status():

/usr/local/mongodb$ mongo MongoDB shell version: 2.4.8 connecting to: test Server has startup warnings: Mon Dec 16 14:30:46.976 [initandlisten] Mon Dec 16 14:30:46.977 [initandlisten] \ WARNING: soft rlimits too low. Number of files is 256, should be at least 1000 replSet0:PRIMARY> rs.status() { "set" : "replSet0", "date" : ISODate("2013-12-17T23:38:52Z"), "myState" : 1, "members" : [ { "_id" : 0, "name" : "127.0.0.0:27017", "health" : 1, "state" : 1, "stateStr" : "PRIMARY", "uptime" : 94086, "optime" : Timestamp(1387322733, 12), "optimeDate" : ISODate("2013-12-17T23:25:33Z"), "self" : true } ], "ok" : 1 } replSet0:PRIMARY>

I’m starting to wonder whether I should build from source and run the river in the debugger?

Thanks, David Haimson

I'd try to to change the host ip address by localhost or host name.

If not successful write a small java app to connect to MongoDB using the java driver.

Many people are using this code with no issue so that's the reason I feel it is a configuration / environment issue.

Let me know how it goes.

Thanks, Richard.

David,

Yes that's better to move this conversion.

You will just need to create a Github login.

Can you please try this version [1]? I have just update the login to try to get a better understanding of the issue.

[1] - https://www.dropbox.com/s/f7xkwpsdkj1kfbc/elasticsearch-river-mongodb-1.7.4-SNAPSHOT.zip

Thanks, Richard.

Richard:

I have installed your 1.7.4 SNAPSHOT version, and reset everything as before. The log:

[2013-12-18 11:01:56,790][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[34381], build[36897d0/2013-11-13T12:06:54Z] [2013-12-18 11:01:56,791][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-18 11:01:56,821][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-18 11:01:58,403][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-18 11:01:58,464][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-18 11:01:58,464][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-18 11:01:58,535][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2013-12-18 11:02:01,588][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][3qnFL_l5Ti64cbK8kso4AQ][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-18 11:02:01,619][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/3qnFL_l5Ti64cbK8kso4AQ [2013-12-18 11:02:01,632][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2013-12-18 11:02:01,632][INFO ][node ] [Devil's Sooty Brother] started [2013-12-18 11:02:01,911][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2013-12-18 11:02:03,504][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 11:02:03,536][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2013-12-18 11:02:03,538][INFO ][river.mongodb ] Parse river settings for units_river [2013-12-18 11:02:03,540][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-18 11:02:03,540][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017 [2013-12-18 11:02:03,557][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2013-12-18 11:02:03,560][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2013-12-18 11:02:03,562][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2013-12-18 11:02:03,565][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] [2013-12-18 11:02:03,566][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[1d328a5] - time[2013-12-18T15:55:08Z] [2013-12-18 11:02:03,566][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2013-12-18 11:02:03,567][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 11:02:03,602][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2013-12-18 11:02:03,682][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: admin - isAuthenticated: false [2013-12-18 11:02:03,682][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with admin

As you can see, the last part is the same as before - no "[INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB version - 2.4.8".

I am concerned that the river may be silently quitting on an exception. If the river plugin gets an exception, does it or ES log it?

I see you added a new version "Throw exception if config database does not exist." Of course we're not getting that far, since, as we've seen, the logger.info call on line 248 isn't happening.

Thanks, David Haimson

River.start method is surrounded by a try catch(Throwable) so all exceptions are captured. So it seems the river is able to get `admindatabase butCommandResult cr = adminDb.command(new BasicDBObject("serverStatus", 1));`` would not return.

Can you try to execute serverStatus [1] from Mongo shell? Does it work? If yes what is returned?

[1] - http://docs.mongodb.org/manual/reference/command/serverStatus/

use admin db.serverStatus()

/* 0 */ { "host" : "coelacanth", "version" : "2.4.8", "process" : "mongod", "pid" : 34325, "uptime" : 4588, "uptimeMillis" : NumberLong(4588344), "uptimeEstimate" : 4256, "localTime" : ISODate("2013-12-18T12:17:57.857-07:00"), "asserts" : { "regular" : 0, "warning" : 0, "msg" : 0, "user" : 0, "rollovers" : 0 }, "backgroundFlushing" : { "flushes" : 76, "total_ms" : 292, "average_ms" : 3.842105263157895, "last_ms" : 4, "last_finished" : ISODate("2013-12-18T12:17:28.094-07:00") }, "connections" : { "current" : 6, "available" : 198, "totalCreated" : NumberLong(35) }, "cursors" : { "totalOpen" : 0, "clientCursors_size" : 0, "timedOut" : 0 }, "dur" : { "commits" : 29, "journaledMB" : 0, "writeToDataFilesMB" : 0, "compression" : 0, "commitsInWriteLock" : 0, "earlyCommits" : 0, "timeMs" : { "dt" : 3025, "prepLogBuffer" : 0, "writeToJournal" : 0, "writeToDataFiles" : 0, "remapPrivateView" : 0 } }, "extra_info" : { "note" : "fields vary by platform", "page_faults" : 733 }, "globalLock" : { "totalTime" : NumberLong(4588344000), "lockTime" : NumberLong(125989), "currentQueue" : { "total" : 0, "readers" : 0, "writers" : 0 }, "activeClients" : { "total" : 0, "readers" : 0, "writers" : 0 } }, "indexCounters" : { "accesses" : 0, "hits" : 0, "misses" : 0, "resets" : 0, "missRatio" : 0 }, "locks" : { "." : { "timeLockedMicros" : { "R" : NumberLong(162453), "W" : NumberLong(125989) }, "timeAcquiringMicros" : { "R" : NumberLong(86321), "W" : NumberLong(13307) } }, "admin" : { "timeLockedMicros" : { "r" : NumberLong(11742), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(283), "w" : NumberLong(0) } }, "local" : { "timeLockedMicros" : { "r" : NumberLong(18583), "w" : NumberLong(2) }, "timeAcquiringMicros" : { "r" : NumberLong(1321), "w" : NumberLong(6010) } }, "bulbLog" : { "timeLockedMicros" : { "r" : NumberLong(9960), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(257), "w" : NumberLong(0) } }, "bulbJUnit" : { "timeLockedMicros" : { "r" : NumberLong(3175), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(162), "w" : NumberLong(0) } }, "bulbDev" : { "timeLockedMicros" : { "r" : NumberLong(3578), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(241), "w" : NumberLong(0) } } }, "network" : { "bytesIn" : 48198, "bytesOut" : 185697, "numRequests" : 832 }, "opcounters" : { "insert" : 1, "query" : 296, "update" : 0, "delete" : 0, "getmore" : 0, "command" : 798 }, "opcountersRepl" : { "insert" : 0, "query" : 0, "update" : 0, "delete" : 0, "getmore" : 0, "command" : 0 }, "recordStats" : { "accessesNotInMemory" : 2, "pageFaultExceptionsThrown" : 0, "admin" : { "accessesNotInMemory" : 1, "pageFaultExceptionsThrown" : 0 }, "bulbDev" : { "accessesNotInMemory" : 0, "pageFaultExceptionsThrown" : 0 }, "bulbJUnit" : { "accessesNotInMemory" : 0, "pageFaultExceptionsThrown" : 0 }, "bulbLog" : { "accessesNotInMemory" : 0, "pageFaultExceptionsThrown" : 0 }, "local" : { "accessesNotInMemory" : 1, "pageFaultExceptionsThrown" : 0 } }, "repl" : { "setName" : "replSet0", "ismaster" : true, "secondary" : false, "hosts" : [ "127.0.0.0:27017" ], "primary" : "127.0.0.0:27017", "me" : "127.0.0.0:27017" }, "writeBacksQueued" : false, "mem" : { "bits" : 64, "resident" : 10, "virtual" : 3861, "supported" : true, "mapped" : 656, "mappedWithJournal" : 1312 }, "metrics" : { "document" : { "deleted" : NumberLong(0), "inserted" : NumberLong(1), "returned" : NumberLong(222), "updated" : NumberLong(0) }, "getLastError" : { "wtime" : { "num" : 0, "totalMillis" : 0 }, "wtimeouts" : NumberLong(0) }, "operation" : { "fastmod" : NumberLong(0), "idhack" : NumberLong(0), "scanAndOrder" : NumberLong(0) }, "queryExecutor" : { "scanned" : NumberLong(3134) }, "record" : { "moves" : NumberLong(0) }, "repl" : { "apply" : { "batches" : { "num" : 0, "totalMillis" : 0 }, "ops" : NumberLong(0) }, "buffer" : { "count" : NumberLong(0), "maxSizeBytes" : 268435456, "sizeBytes" : NumberLong(0) }, "network" : { "bytes" : NumberLong(0), "getmores" : { "num" : 0, "totalMillis" : 0 }, "ops" : NumberLong(0), "readersCreated" : NumberLong(3) }, "oplog" : { "insert" : { "num" : 0, "totalMillis" : 0 }, "insertBytes" : NumberLong(0) }, "preload" : { "docs" : { "num" : 0, "totalMillis" : 0 }, "indexes" : { "num" : 0, "totalMillis" : 0 } } }, "ttl" : { "deletedDocuments" : NumberLong(0), "passes" : NumberLong(76) } }, "ok" : 1 }

[2013-12-18 12:54:08,853][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[37357], build[36897d0/2013-11-13T12:06:54Z] [2013-12-18 12:54:08,853][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-18 12:54:08,889][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-18 12:54:10,454][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-18 12:54:10,518][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-18 12:54:10,518][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-18 12:54:10,586][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2013-12-18 12:54:13,638][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][OfqH_9lGRAWZWORPUwn7yA][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-18 12:54:13,671][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/OfqH_9lGRAWZWORPUwn7yA [2013-12-18 12:54:13,682][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2013-12-18 12:54:13,683][INFO ][node ] [Devil's Sooty Brother] started [2013-12-18 12:54:13,968][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2013-12-18 12:54:15,560][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 12:54:15,566][INFO ][river.routing ] [Devil's Sooty Brother] no river _meta document found, retrying in 1000 ms [2013-12-18 12:54:16,587][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2013-12-18 12:54:16,588][INFO ][river.mongodb ] Parse river settings for units_river [2013-12-18 12:54:16,590][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-18 12:54:16,590][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017 [2013-12-18 12:54:16,601][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2013-12-18 12:54:16,602][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2013-12-18 12:54:16,603][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2013-12-18 12:54:16,607][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] [2013-12-18 12:54:16,608][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[1d328a5] - time[2013-12-18T19:47:12Z] [2013-12-18 12:54:16,608][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2013-12-18 12:54:16,608][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 12:54:16,646][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2013-12-18 12:54:16,723][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: admin - isAuthenticated: false [2013-12-18 12:54:16,723][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with admin

I'm pretty sure I've managed to install your snapshots. What I'm doing is copying the new jar file into elasticsearch/plugins/river-mongodb (replacing the previous one) and then restarting elasticsearch. But the hash that appears on the river's INFO log message is the same as before, and the log is otherwise unchanged:

[2013-12-18 13:13:43,063][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[37943], build[36897d0/2013-11-13T12:06:54Z] [2013-12-18 13:13:43,064][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-18 13:13:43,097][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-18 13:13:44,659][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-18 13:13:44,731][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-18 13:13:44,732][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-18 13:13:44,800][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/192.168.107.228:9300]}, publish_address {inet[/192.168.107.228:9300]} [2013-12-18 13:13:47,853][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][Kxg_xuPISj2iEG-St7tXUA][inet[/192.168.107.228:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-18 13:13:47,888][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/Kxg_xuPISj2iEG-St7tXUA [2013-12-18 13:13:47,899][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/192.168.107.228:9200]}, publish_address {inet[/192.168.107.228:9200]} [2013-12-18 13:13:47,899][INFO ][node ] [Devil's Sooty Brother] started [2013-12-18 13:13:48,176][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2013-12-18 13:13:49,782][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 13:13:49,811][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2013-12-18 13:13:49,812][INFO ][river.mongodb ] Parse river settings for units_river [2013-12-18 13:13:49,814][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-18 13:13:49,815][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017 [2013-12-18 13:13:49,831][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2013-12-18 13:13:49,833][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2013-12-18 13:13:49,834][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2013-12-18 13:13:49,837][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] [2013-12-18 13:13:49,838][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[1d328a5] - time[2013-12-18T20:08:45Z] [2013-12-18 13:13:49,838][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2013-12-18 13:13:49,839][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 13:13:49,874][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2013-12-18 13:13:49,954][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: admin - authenticated: false [2013-12-18 13:13:49,955][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with admin

What would I have to do to set this up in Eclipse so that I can debug the MongoDBRiver in conjunction with elasticsearch?

The hash is the same because I have not commited to Github to additional logging. But I changed the logging from isAuthenticated to authenticated just to confirm the latest snapshot version was installed. It seems to be an issue with accessing admin database:

    private DB getAdminDb() {
        if (adminDb == null) {
            adminDb = getMongoClient().getDB(MONGODB_ADMIN_DATABASE);
            if (logger.isTraceEnabled()) {
                logger.trace("MongoAdminUser: {} - authenticated: {}", definition.getMongoAdminUser(), adminDb.isAuthenticated());
            }
            if (!definition.getMongoAdminUser().isEmpty() && !definition.getMongoAdminPassword().isEmpty() && !adminDb.isAuthenticated()) {
                logger.info("Authenticate {} with {}", MONGODB_ADMIN_DATABASE, definition.getMongoAdminUser());

                try {
                    CommandResult cmd = adminDb.authenticateCommand(definition.getMongoAdminUser(), definition.getMongoAdminPassword()
                            .toCharArray());
                    if (!cmd.ok()) {
                        logger.error("Autenticatication failed for {}: {}", MONGODB_ADMIN_DATABASE, cmd.getErrorMessage());
                    } else {
                        logger.trace("authenticateCommand: {} - isAuthenticated: {}", cmd, adminDb.isAuthenticated());
                    }
                } catch (MongoException mEx) {
                    logger.warn("getAdminDb() failed", mEx);
                }
            }
        }
        if (adminDb == null) {
            throw new ElasticSearchException(String.format("Could not get %s database from MongoDB", MONGODB_ADMIN_DATABASE));
        }
        return adminDb;
    }

We have in the log: Authenticate admin with admin but we should get a new trace or exception after that.

I would suggest to run this specific method in a simple java app.

BTW - did you try to change host using hostname or localhost?

Regarding the getAdminDb function: I restored my configuration to the way it was originally (no admin db, no auth setting in mongod.conf). See log below.

I see no "Authenticate admin with admin" info message, as expected. I do see the "MongoAdminUser: - authenticated: false" message, also as expected. I also see the message "Found admin database", which is surprising, because I have dropped that database, and it does not exist. The last thing I see is the "About to execute serverStatus" message.

I will try to set up a sample program with your getAdminDb function in it.

[2013-12-18 13:35:38,016][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[38727], build[36897d0/2013-11-13T12:06:54Z] [2013-12-18 13:35:38,017][INFO ][node ] [Devil's Sooty Brother] initializing ... [2013-12-18 13:35:38,047][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2013-12-18 13:35:39,618][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2013-12-18 13:35:39,679][INFO ][node ] [Devil's Sooty Brother] initialized [2013-12-18 13:35:39,679][INFO ][node ] [Devil's Sooty Brother] starting ... [2013-12-18 13:35:39,749][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2013-12-18 13:35:42,801][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][AI8k6LJSSwyjSnMABQWCcQ][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2013-12-18 13:35:42,845][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/AI8k6LJSSwyjSnMABQWCcQ [2013-12-18 13:35:42,856][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2013-12-18 13:35:42,857][INFO ][node ] [Devil's Sooty Brother] started [2013-12-18 13:35:43,140][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2013-12-18 13:35:44,732][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 13:35:44,762][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2013-12-18 13:35:44,763][INFO ][river.mongodb ] Parse river settings for units_river [2013-12-18 13:35:44,766][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-18 13:35:44,766][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017 [2013-12-18 13:35:44,781][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2013-12-18 13:35:44,783][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2013-12-18 13:35:44,784][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2013-12-18 13:35:44,788][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017] [2013-12-18 13:35:44,789][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[1d328a5] - time[2013-12-18T20:08:45Z] [2013-12-18 13:35:44,789][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2013-12-18 13:35:44,789][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river [2013-12-18 13:35:44,824][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2013-12-18 13:35:44,909][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: - authenticated: false [2013-12-18 13:35:44,909][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Found admin database [2013-12-18 13:35:44,911][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] About to execute: { "serverStatus" : 1 , "asserts" : 0 , "backgroundFlushing" : 0 , "connections" : 0 , "cursors" : 0 , "dur" : 0 , "extra_info" : 0 , "globalLock" : 0 , "indexCounters" : 0 , "locks" : 0 , "metrics" : 0 , "network" : 0 , "opcounters" : 0 , "opcountersRepl" : 0 , "recordStats" : 0 , "repl" : 0}

Regarding your question "did you try to change host using hostname or localhost?" Do you want me to change bind_ip in mongod.conf to localhost? Or do you want me to change host in the servers array in the river config to localhost? Or both? localhost resolves to 127.0.0.1, of course. The local hostname, that resolves to my local IP address, as used by elasticsearch (replaced by IP_ADDRESS_HERE in the log entries above).

I'd try to only update it in the river configuration.

In the river configuration, I changed the config for "host" in the "server" config from "127.0.0.0" to "localhost". This made no difference. In the elasticsearch log, it shows it as 127.0.0.0 anyway:

[2013-12-18 16:19:47,726][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=127.0.0.0}] [2013-12-18 16:19:47,726][INFO ][river.mongodb ] Server: 127.0.0.0 - 27017

[2013-12-18 16:19:47,749][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [127.0.0.0], port [27017]

I put together a test app around the MongoDbRiver getAdminDb, getConfigDb, and isMongos methods. They all behave as expected.

I noticed a couple of surprising things:

Recall that I have no admin database. When I do:

adminDb = getMongoClient().getDB(MONGODB_ADMIN_DATABASE);

adminDb is not null; I don't know how to tell, but it appears to me that the MongoDB api is returning some sort of pseudo admin database structure. I don't know whether it matters, but it's useful to know.

adminDb.isAuthenticated() returns false, as expected. Unfortunately there does not appear to be any way through the MongoDB api to tell whether "noauth" is configured. That would be useful to shortcut a lot of tests that are not meaningful if noauth is true, which it is on my system. Let me know if you do know a way to find that out.

I've had to change the code for these methods somewhat, since I'm not integrated with elasticsearch. Of course I changed them as little as possible. I believe they are doing the same thing in my test program that they are in the river.

I was unable to configure tracing, for some reason, but I logged what the Trace config would have logged:

Dec 18, 2013 4:47:05 PM org.elasticsearch.river.mongodb.TestAdminDb INFO: MongoDB version - 2.4.8 Dec 18, 2013 4:47:07 PM org.elasticsearch.river.mongodb.TestAdminDb INFO: serverStatus: { "serverUsed" : "/127.0.0.1:27017" , "host" : "coelacanth" , "version" : "2.4.8" , "process" : "mongod" , "pid" : 34325 , "uptime" : 20735.0 , "uptimeMillis" : 20735467 , "uptimeEstimate" : 19234.0 , "localTime" : { "$date" : "2013-12-18T23:47:04.980Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 0 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 345 , "total_ms" : 1466 , "average_ms" : 4.249275362318841 , "last_ms" : 5 , "last_finished" : { "$date" : "2013-12-18T23:46:22.988Z"}} , "connections" : { "current" : 3 , "available" : 201 , "totalCreated" : 56} , "cursors" : { "totalOpen" : 0 , "clientCursors_size" : 0 , "timedOut" : 0} , "dur" : { "commits" : 29 , "journaledMB" : 0.0 , "writeToDataFilesMB" : 0.0 , "compression" : 0.0 , "commitsInWriteLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3020 , "prepLogBuffer" : 0 , "writeToJournal" : 0 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "page_faults" : 733} , "globalLock" : { "totalTime" : 20735467000 , "lockTime" : 421527 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 0 , "readers" : 0 , "writers" : 0}} , "indexCounters" : { "accesses" : 0 , "hits" : 0 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 711453 , "W" : 421527} , "timeAcquiringMicros" : { "R" : 386772 , "W" : 59976}} , "admin" : { "timeLockedMicros" : { "r" : 24309 , "w" : 0} , "timeAcquiringMicros" : { "r" : 583 , "w" : 0}} , "local" : { "timeLockedMicros" : { "r" : 35040 , "w" : 2} , "timeAcquiringMicros" : { "r" : 5617 , "w" : 6010}} , "bulbLog" : { "timeLockedMicros" : { "r" : 22314 , "w" : 0} , "timeAcquiringMicros" : { "r" : 1005 , "w" : 0}} , "bulbJUnit" : { "timeLockedMicros" : { "r" : 22158 , "w" : 0} , "timeAcquiringMicros" : { "r" : 975 , "w" : 0}} , "bulbDev" : { "timeLockedMicros" : { "r" : 43348 , "w" : 0} , "timeAcquiringMicros" : { "r" : 1939 , "w" : 0}}} , "network" : { "bytesIn" : 113821 , "bytesOut" : 282132 , "numRequests" : 1978} , "opcounters" : { "insert" : 1 , "query" : 1455 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 1937} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 2 , "pageFaultExceptionsThrown" : 0 , "bulbDev" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "bulbJUnit" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "bulbLog" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 0}} , "repl" : { "setName" : "replSet0" , "ismaster" : true , "secondary" : false , "hosts" : [ "127.0.0.0:27017"] , "primary" : "127.0.0.0:27017" , "me" : "127.0.0.0:27017"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 9 , "virtual" : 3700 , "supported" : true , "mapped" : 576 , "mappedWithJournal" : 1152} , "metrics" : { "document" : { "deleted" : 0 , "inserted" : 1 , "returned" : 236 , "updated" : 0} , "getLastError" : { "wtime" : { "num" : 0 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 0 , "idhack" : 0 , "scanAndOrder" : 0} , "queryExecutor" : { "scanned" : 19438} , "record" : { "moves" : 0} , "repl" : { "apply" : { "batches" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0} , "buffer" : { "count" : 0 , "maxSizeBytes" : 268435456 , "sizeBytes" : 0} , "network" : { "bytes" : 0 , "getmores" : { "num" : 0 , "totalMillis" : 0} , "ops" : 0 , "readersCreated" : 3} , "oplog" : { "insert" : { "num" : 2 , "totalMillis" : 0} , "insertBytes" : 180} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 345}} , "ok" : 1.0} Dec 18, 2013 4:47:29 PM org.elasticsearch.river.mongodb.TestAdminDb INFO: process: mongod

admin is a system database so I believe it is always accessible.
Regarding authentication I have been monitoring the options available from MongoDB but so far there is no safe way to find out if it requires authentication or not.
Are you saying that the same code is running just fine as standalone app? Could you post the code?

Yes, it does. Let me clean it up a bit, and I'll post it.

I need to work on something else today. I may be able to get back to this tomorrow.

Richard:

I've been on Xmas vacation, but I'm back now. It still doesn't work. Current status is as follows:

I have mongodb 2.4.8, ElasticSearch 0.90.7, and MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[1d328a5] - time[2013-12-18T20:08:45Z].

This is running on Mac OS 10.9.1.

Results reported below are with mongod configured "auth = true" and an admin user configured as described below.

If I set "noauth = true" and remove the admin user, the log is a bit different, but the river still fails with "can't find a master".

This suggests to me that mongodb is not configured correctly, but I'm not seeing what's wrong.

mongod.conf:


fork = true
bind_ip = 127.0.0.1
port = 27017
quiet = true
dbpath = /usr/local/mongodb_data
logpath = /var/log/mongodb/mongod.log
logappend = true
journal = true
replSet = replSet0
auth = true

mongodb admin user:

db.addUser({
    user:"admin",
    pwd:"admin",
    roles:[
        "readWriteAnyDatabase",
        "userAdminAnyDatabase",
        "clusterAdmin"
]})

river configuration:

curl -XGET "IP_ADDRESS_HERE:9200/_river/units_river/_meta?pretty=true"
{
  "_index" : "_river",
  "_type" : "units_river",
  "_id" : "_meta",
  "_version" : 1,
  "exists" : true, "_source" : 
{
  "type": "mongodb",
  "mongodb": {
    "servers": [
      { "host": "localhost", "port": 27017 }
    ],
    "options": {
      "secondary_read_preference": true,
      "import_all_collections": false,
      "skip_initial_import": false,
      "store_statistics": true
    },
    "credentials": [
      { "db": "local", "user": "user", "password": "user" },
      { "db": "admin", "user": "admin", "password": "admin" }
    ],
    "db": "bulbDev", 
    "collection": "units", 
    "gridfs": false
  }, 
  "index": { 
    "name": "units_index", 
    "type": "unit"
   }
}
}

If I connect to this mongodb using mongo localhost:27017, I get the following results:

MongoDB shell version: 2.4.8
connecting to: localhost:27017/test
> use admin
switched to db admin
> db.auth("admin","admin")
1
replSet0:PRIMARY> rs.status()
{
    "set" : "replSet0",
    "date" : ISODate("2014-01-02T20:24:55Z"),
    "myState" : 1,
    "members" : [
        {
            "_id" : 0,
            "name" : "127.0.0.0:27017",
            "health" : 1,
            "state" : 1,
            "stateStr" : "PRIMARY",
            "uptime" : 1686,
            "optime" : Timestamp(1388691385, 2),
            "optimeDate" : ISODate("2014-01-02T19:36:25Z"),
            "self" : true
        }
    ],
    "ok" : 1
}
replSet0:PRIMARY> rs.isMaster()
{
    "setName" : "replSet0",
    "ismaster" : true,
    "secondary" : false,
    "hosts" : [
        "127.0.0.0:27017"
    ],
    "primary" : "127.0.0.0:27017",
    "me" : "127.0.0.0:27017",
    "maxBsonObjectSize" : 16777216,
    "maxMessageSizeBytes" : 48000000,
    "localTime" : ISODate("2014-01-02T20:25:01.477Z"),
    "ok" : 1
}

As you can see, a replSet is configured, but it has only one member. Clearly this is a degenerate configuration, but this is just my development system, and there is only one copy of the data.

Can you suggest a better alternative?

When I start up the river, I get the error "can't find a master".

ElasticSearch log at startup:

[2014-01-02 12:56:52,064][INFO ][transport                ] [Devil's Sooty Brother] bound_address {inet[/192.168.107.228:9300]}, publish_address {inet[/192.168.107.228:9300]}
[2014-01-02 12:56:55,116][INFO ][cluster.service          ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][wkPkL2UBRg-DCFWw8hEnlA][inet[/192.168.107.228:9300]]{master=true}, reason: zen-disco-join (elected_as_master)
[2014-01-02 12:56:55,149][INFO ][discovery                ] [Devil's Sooty Brother] Zaragossa/wkPkL2UBRg-DCFWw8hEnlA
[2014-01-02 12:56:55,160][INFO ][http                     ] [Devil's Sooty Brother] bound_address {inet[/192.168.107.228:9200]}, publish_address {inet[/192.168.107.228:9200]}
[2014-01-02 12:56:55,161][INFO ][node                     ] [Devil's Sooty Brother] started
[2014-01-02 12:56:55,437][INFO ][gateway                  ] [Devil's Sooty Brother] recovered [1] indices into cluster_state
[2014-01-02 12:56:57,058][INFO ][cluster.metadata         ] [Devil's Sooty Brother] [_river] update_mapping [units_river] (dynamic)
[2014-01-02 12:56:57,066][INFO ][river.routing            ] [Devil's Sooty Brother] no river _meta document found, retrying in 1000 ms
[2014-01-02 12:56:58,084][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river]
[2014-01-02 12:56:58,085][INFO ][river.mongodb            ] Parse river settings for units_river
[2014-01-02 12:56:58,088][TRACE][river.mongodb            ] mongoServersSettings: [{port=27017, host=localhost}]
[2014-01-02 12:56:58,088][INFO ][river.mongodb            ] Server: localhost - 27017
[2014-01-02 12:56:58,102][TRACE][river.mongodb            ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false}
[2014-01-02 12:56:58,104][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river
[2014-01-02 12:56:58,105][DEBUG][river.mongodb.util       ] setRiverStatus called with units_river - RUNNING
[2014-01-02 12:56:58,110][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [localhost], port [27017]
[2014-01-02 12:56:58,111][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[1d328a5] - time[2013-12-18T20:08:45Z]
[2014-01-02 12:56:58,111][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit]
[2014-01-02 12:56:58,111][INFO ][cluster.metadata         ] [Devil's Sooty Brother] [_river] update_mapping [units_river] (dynamic)
[2014-01-02 12:56:58,148][INFO ][cluster.metadata         ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings []
[2014-01-02 12:56:58,226][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: admin - authenticated: false
[2014-01-02 12:56:58,227][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Authenticate admin with admin
[2014-01-02 12:57:38,256][WARN ][org.elasticsearch.river.mongodb.MongoDBRiver] getAdminDb() failed
com.mongodb.MongoException: can't find a master
    at com.mongodb.DBTCPConnector.checkMaster(DBTCPConnector.java:517)
    at com.mongodb.DBTCPConnector.authenticate(DBTCPConnector.java:631)
    at com.mongodb.DBApiLayer.doAuthenticate(DBApiLayer.java:180)
    at com.mongodb.DB.authenticateCommandHelper(DB.java:631)
    at com.mongodb.DB.authenticateCommand(DB.java:610)
    at org.elasticsearch.river.mongodb.MongoDBRiver.getAdminDb(MongoDBRiver.java:302)
    at org.elasticsearch.river.mongodb.MongoDBRiver.isMongos(MongoDBRiver.java:245)
    at org.elasticsearch.river.mongodb.MongoDBRiver.start(MongoDBRiver.java:200)
    at org.elasticsearch.river.RiversService.createRiver(RiversService.java:146)
    at org.elasticsearch.river.RiversService$ApplyRivers$2.onResponse(RiversService.java:271)
    at org.elasticsearch.river.RiversService$ApplyRivers$2.onResponse(RiversService.java:265)
    at org.elasticsearch.action.support.TransportAction$ThreadedActionListener$1.run(TransportAction.java:93)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
    at java.lang.Thread.run(Thread.java:695)
[2014-01-02 12:57:38,259][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Found admin database
[2014-01-02 12:57:38,260][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] About to execute: { "serverStatus" : 1 , "asserts" : 0 , "backgroundFlushing" : 0 , "connections" : 0 , "cursors" : 0 , "dur" : 0 , "extra_info" : 0 , "globalLock" : 0 , "indexCounters" : 0 , "locks" : 0 , "metrics" : 0 , "network" : 0 , "opcounters" : 0 , "opcountersRepl" : 0 , "recordStats" : 0 , "repl" : 0}
[2014-01-02 12:57:58,261][WARN ][org.elasticsearch.river.mongodb.MongoDBRiver] Fail to start river units_river
com.mongodb.MongoException: can't find a master
    at com.mongodb.DBTCPConnector.checkMaster(DBTCPConnector.java:517)
    at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:236)
    at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:216)
    at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:288)
    at com.mongodb.DB.command(DB.java:262)
    at com.mongodb.DB.command(DB.java:244)
    at com.mongodb.DB.command(DB.java:301)
    at com.mongodb.DB.command(DB.java:199)
    at org.elasticsearch.river.mongodb.MongoDBRiver.isMongos(MongoDBRiver.java:258)
    at org.elasticsearch.river.mongodb.MongoDBRiver.start(MongoDBRiver.java:200)
    at org.elasticsearch.river.RiversService.createRiver(RiversService.java:146)
    at org.elasticsearch.river.RiversService$ApplyRivers$2.onResponse(RiversService.java:271)
    at org.elasticsearch.river.RiversService$ApplyRivers$2.onResponse(RiversService.java:265)
    at org.elasticsearch.action.support.TransportAction$ThreadedActionListener$1.run(TransportAction.java:93)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
    at java.lang.Thread.run(Thread.java:695)
[2014-01-02 12:57:58,262][DEBUG][river.mongodb.util       ] setRiverStatus called with units_river - START_FAILED
[2014-01-02 12:57:58,272][INFO ][cluster.metadata         ] [Devil's Sooty Brother] [_river] update_mapping [units_river] (dynamic)

I wrote a test program based on MongoDBRiver.java that does more or less the same thing that MongoDBRiver is trying to do up to the isMongos call, based on the "Fix #190" version of MongoDBRiver.java. It succeeds with the following output:

Jan 02, 2014 1:05:23 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: Opening Mongo client
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: MongoAdminUser: admin - isAuthenticated: false
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: Authenticating database admin as user admin
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: isMongos: About to execute: { "serverStatus" : 1 , "asserts" : 0 , "backgroundFlushing" : 0 , "connections" : 0 , "cursors" : 0 , "dur" : 0 , "extra_info" : 0 , "globalLock" : 0 , "indexCounters" : 0 , "locks" : 0 , "metrics" : 0 , "network" : 0 , "opcounters" : 0 , "opcountersRepl" : 0 , "recordStats" : 0 , "repl" : 0}
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: isMongos: MongoDB version: 2.4.8
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: isMongos: serverStatus: { "serverUsed" : "localhost/127.0.0.1:27017" , "host" : "coelacanth" , "version" : "2.4.8" , "process" : "mongod" , "pid" : 58919 , "uptime" : 520.0 , "uptimeMillis" : 519359 , "uptimeEstimate" : 481.0 , "localTime" : { "$date" : "2014-01-02T20:05:29.259Z"} , "ok" : 1.0}
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: process: mongod
Jan 02, 2014 1:05:29 PM org.elasticsearch.river.mongodb.TestIsMongos
INFO: Closing Mongo client

Source code for this test program is as follows:

/*
 * Based on:
 * https://github.com/richardwilly98/elasticsearch-river-mongodb/blob/master/src/main/java/org/elasticsearch/river/mongodb/MongoDBRiver.java
 */

/*
 * Licensed to Elastic Search and Shay Banon under one
 * or more contributor license agreements.  See the NOTICE file
 * distributed with this work for additional information
 * regarding copyright ownership. Elastic Search licenses this
 * file to you under the Apache License, Version 2.0 (the
 * "License"); you may not use this file except in compliance
 * with the License.  You may obtain a copy of the License at
 *
 *    http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing,
 * software distributed under the License is distributed on an
 * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
 * KIND, either express or implied.  See the License for the
 * specific language governing permissions and limitations
 * under the License.
 */
package org.elasticsearch.river.mongodb;

import java.net.UnknownHostException;
import java.util.List;

import org.elasticsearch.client.Client;
import org.elasticsearch.common.collect.ImmutableMap;
import org.elasticsearch.common.collect.Lists;
import org.elasticsearch.common.logging.ESLogger;
import org.elasticsearch.common.logging.ESLoggerFactory;
import org.elasticsearch.river.RiverName;
import org.elasticsearch.river.RiverSettings;
import org.elasticsearch.script.ScriptService;

import com.mongodb.BasicDBObjectBuilder;
import com.mongodb.CommandResult;
import com.mongodb.DB;
import com.mongodb.DBObject;
import com.mongodb.Mongo;
import com.mongodb.MongoClient;
import com.mongodb.MongoClientOptions;
import com.mongodb.MongoException;
import com.mongodb.ReadPreference;
import com.mongodb.ServerAddress;

/**
 * @author richardwilly98 (Richard Louapre)
 * @author flaper87 (Flavio Percoco Premoli)
 * @author aparo (Alberto Paro)
 * @author kryptt (Rodolfo Hansen)
 * @author benmccann (Ben McCann)
 * @author haimson (David Haimson)
 */
public class TestIsMongos {

    public final static String TYPE = "mongodb";
    public final static String NAME = "mongodb-river";
    public final static String STATUS_ID = "_riverstatus";
    public final static String STATUS_FIELD = "status";
    public final static String DESCRIPTION = "MongoDB River Plugin";
    public final static String LAST_TIMESTAMP_FIELD = "_last_ts";
    public final static String MONGODB_LOCAL_DATABASE = "local";
    public final static String MONGODB_ADMIN_DATABASE = "admin";
    public final static String MONGODB_CONFIG_DATABASE = "config";
    public final static String MONGODB_ID_FIELD = "_id";
    public final static String MONGODB_IN_OPERATOR = "$in";
    public final static String MONGODB_OR_OPERATOR = "$or";
    public final static String MONGODB_AND_OPERATOR = "$and";
    public final static String MONGODB_NATURAL_OPERATOR = "$natural";
    public final static String OPLOG_COLLECTION = "oplog.rs";
    public final static String OPLOG_NAMESPACE = "ns";
    public final static String OPLOG_NAMESPACE_COMMAND = "$cmd";
    public final static String OPLOG_OBJECT = "o";
    public final static String OPLOG_UPDATE = "o2";
    public final static String OPLOG_OPERATION = "op";
    public final static String OPLOG_UPDATE_OPERATION = "u";
    public final static String OPLOG_INSERT_OPERATION = "i";
    public final static String OPLOG_DELETE_OPERATION = "d";
    public final static String OPLOG_COMMAND_OPERATION = "c";
    public final static String OPLOG_DROP_COMMAND_OPERATION = "drop";
    public final static String OPLOG_DROP_DATABASE_COMMAND_OPERATION = "dropDatabase";
    public final static String OPLOG_TIMESTAMP = "ts";
    public final static String OPLOG_FROM_MIGRATE = "fromMigrate";
    public final static String GRIDFS_FILES_SUFFIX = ".files";
    public final static String GRIDFS_CHUNKS_SUFFIX = ".chunks";

    static final ESLogger logger = ESLoggerFactory.getLogger(TestIsMongos.class.getName());

    protected final MongoDBRiverDefinition definition = null;
    protected final Client client = null;
    protected final ScriptService scriptService = null;
    protected final SharedContext context = null;

    protected volatile List<Thread> tailerThreads = Lists.newArrayList();
    protected volatile Thread indexerThread;
    protected volatile Thread statusThread;
    protected volatile boolean startInvoked = false;

    protected RiverName riverName;
    protected RiverSettings settings = null;

    private Mongo mongo;
    private DB adminDb;

    private String mongoDbHost = "localhost";
    private int mongoDbPort = 27017;
    private String adminUser;
    private String adminPassword;

    public static void main(String[] args) {
        // No admin user or password.
        // Works correctly if MongoDB is configured with "noauth = true".
        TestIsMongos testIsMongos;
//      testIsMongos = new TestIsMongos(null, null);
//      testIsMongos.test();

        // Set admin user and password.
        // Works correctly if MongoDB is configured with "auth = true",
        // and the specified user is correctly configured:
        // { user:"admin",pwd:"admin",roles:["readWriteAnyDatabase","userAdminAnyDatabase","clusterAdmin"] }
        testIsMongos = new TestIsMongos("admin", "admin");
        testIsMongos.test();
    }

    public TestIsMongos(String adminUser, String adminPassword) {
        this.adminUser = adminUser;
        this.adminPassword = adminPassword;
    }

    private void test() {
        getAdminDb();
        getConfigDb();
        isMongos();
        closeMongoClient();
    }

    private boolean isMongos() {
        if (adminDb == null) {
            logger.info("isMongos: no adminDb");
            return false;
        }
        DBObject command = BasicDBObjectBuilder.start(
                ImmutableMap.builder().put("serverStatus", 1).put("asserts", 0).put("backgroundFlushing", 0).put("connections", 0)
                        .put("cursors", 0).put("dur", 0).put("extra_info", 0).put("globalLock", 0).put("indexCounters", 0).put("locks", 0)
                        .put("metrics", 0).put("network", 0).put("opcounters", 0).put("opcountersRepl", 0).put("recordStats", 0)
                        .put("repl", 0).build()).get();
        logger.info("isMongos: About to execute: {}", command);
        CommandResult cr = adminDb.command(command);
        logger.trace("isMongos: Command executed return : {}", cr);

        logger.info("isMongos: MongoDB version: {}", cr.get("version"));
        logger.info("isMongos: serverStatus: {}", cr);

        if (!cr.ok()) {
            logger.warn("isMongos: serverStatus returned error: {}", cr.getErrorMessage());
            return false;
        }

        Object processObject = cr.get("process");
        if (processObject == null) {
            logger.warn("isMongos: no serverStatus.process");
            return false;
        }
        String process = processObject.toString().toLowerCase();
        logger.info("process: {}", process);
        // Fix for https://jira.mongodb.org/browse/SERVER-9160
        return process.contains("mongos");
    }

    private DB getAdminDb() {
        if (adminDb == null) {
            adminDb = getMongoClient().getDB(MONGODB_ADMIN_DATABASE);
            String adminUserString = adminUser != null && !adminUser.isEmpty() ? adminUser : "(none)";
            logger.info("MongoAdminUser: {} - isAuthenticated: {}", adminUserString, adminDb.isAuthenticated());
            if ((adminUser != null && !adminUser.isEmpty()) &&
                    (adminPassword != null && !adminPassword.isEmpty()) &&
                    !getAdminDb().isAuthenticated()) {
                logger.info("Authenticating database {} as user {}", MONGODB_ADMIN_DATABASE, adminUserString);
                try {
                    CommandResult cmd = adminDb.authenticateCommand(adminUser, adminPassword.toCharArray());
                    if (!cmd.ok()) {
                        logger.error("Autenticatication failed for database {}: {}", MONGODB_ADMIN_DATABASE, cmd.getErrorMessage());
                    }
                } catch (MongoException mEx) {
                    logger.error("getAdminDb: Cannot authenticate {} database", MONGODB_ADMIN_DATABASE, mEx);
                    adminDb = null;
                }
            }
        }
        return adminDb;
    }

    private DB getConfigDb() {
        if (adminDb == null) {
            logger.info("getConfigDb: no adminDb");
            return null;
        }
        DB configDb = getMongoClient().getDB(MONGODB_CONFIG_DATABASE);
        if ((adminUser != null && !adminUser.isEmpty()) &&
                (adminPassword != null && !adminPassword.isEmpty())) {
            // auth case
            if (!adminDb.isAuthenticated()) {
                try {
                    configDb = adminDb.getMongo().getDB(MONGODB_CONFIG_DATABASE);
                } catch (MongoException mEx) {
                    logger.warn("getConfigDb: Cannot get {} database", MONGODB_CONFIG_DATABASE, mEx);
                    return null;
                }
            }
        }
        return configDb;
    }

    private Mongo getMongoClient() {                
        if (mongo == null) {
            // mongo = new MongoClient(definition.getMongoServers(), definition.getMongoClientOptions());
            logger.info("Opening Mongo client");
            try {
                // mongo = new MongoClient(new ServerAddress(mongoDbHost, mongoDbPort),
                MongoClientOptions.Builder builder = new MongoClientOptions.Builder();
                builder.readPreference(ReadPreference.secondary());
                builder.socketKeepAlive(true);
                mongo = new MongoClient(new ServerAddress(mongoDbHost, mongoDbPort), builder.build());
            } catch (UnknownHostException ex) {
                logger.error("Host {} not found", mongoDbHost, ex);
                System.exit(-1);
            }
        }
        return mongo;
    }

    private void closeMongoClient() {
        logger.info("Closing Mongo client");
        if (adminDb != null) {
            adminDb = null;
        }
        if (mongo != null) {
            mongo.close();
            mongo = null;
        }
    }
}

OK, I figured it out.

Apparently Mongodb is extremely sensitive to exactly how you switch it between standalone and replicated. I removed the database and followed the instructions at http://docs.mongodb.org/manual/tutorial/convert-standalone-to-replica-set/ precisely, and now it works. Looks to me like a bug in Mongodb. I will try to document the observed problem and submit a bug to them.

On startup, the ES log now looks like this:

[2014-01-06 08:40:55,974][INFO ][node ] [Devil's Sooty Brother] version[0.90.7], pid[91699], build[36897d0/2013-11-13T12:06:54Z] [2014-01-06 08:40:55,974][INFO ][node ] [Devil's Sooty Brother] initializing ... [2014-01-06 08:40:56,053][INFO ][plugins ] [Devil's Sooty Brother] loaded [mongodb-river, mapper-attachments], sites [river-mongodb] [2014-01-06 08:40:58,091][TRACE][rest.action.mongodb ] [Devil's Sooty Brother] RestMongoDBRiverAction - baseUrl: /_river/mongodb [2014-01-06 08:40:58,172][INFO ][node ] [Devil's Sooty Brother] initialized [2014-01-06 08:40:58,172][INFO ][node ] [Devil's Sooty Brother] starting ... [2014-01-06 08:40:58,263][INFO ][transport ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9300]}, publish_address {inet[/IP_ADDRESS_HERE:9300]} [2014-01-06 08:41:01,330][INFO ][cluster.service ] [Devil's Sooty Brother] new_master [Devil's Sooty Brother][gS5AjZVWQY2JujbDe7tQMw][inet[/IP_ADDRESS_HERE:9300]]{master=true}, reason: zen-disco-join (elected_as_master) [2014-01-06 08:41:01,372][INFO ][discovery ] [Devil's Sooty Brother] Zaragossa/gS5AjZVWQY2JujbDe7tQMw [2014-01-06 08:41:01,388][INFO ][http ] [Devil's Sooty Brother] bound_address {inet[/IP_ADDRESS_HERE:9200]}, publish_address {inet[/IP_ADDRESS_HERE:9200]} [2014-01-06 08:41:01,389][INFO ][node ] [Devil's Sooty Brother] started [2014-01-06 08:41:01,821][INFO ][gateway ] [Devil's Sooty Brother] recovered [1] indices into cluster_state [2014-01-06 08:41:01,921][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Initializing river : [units_river] [2014-01-06 08:41:01,922][INFO ][river.mongodb ] Parse river settings for units_river [2014-01-06 08:41:01,925][TRACE][river.mongodb ] mongoServersSettings: [{port=27017, host=localhost}] [2014-01-06 08:41:01,925][INFO ][river.mongodb ] Server: localhost - 27017 [2014-01-06 08:41:01,941][TRACE][river.mongodb ] mongoOptionsSettings: {store_statistics=true, skip_initial_import=false, secondary_read_preference=true, import_all_collections=false} [2014-01-06 08:41:01,943][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] Starting river units_river [2014-01-06 08:41:01,945][DEBUG][river.mongodb.util ] setRiverStatus called with units_river - RUNNING [2014-01-06 08:41:01,980][DEBUG][org.elasticsearch.river.mongodb.MongoDBRiver] Using mongodb server(s): host [localhost], port [27017] [2014-01-06 08:41:01,982][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB River Plugin - version[1.7.4-SNAPSHOT] - hash[${build] - time[2014-01-03T19:23:01Z] [2014-01-06 08:41:01,982][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [5000], gridfs [false], filter [null], db [bulbDev], collection [units], script [null], indexing to [units_index]/[unit] [2014-01-06 08:41:02,016][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] creating index, cause [api], shards [1]/[0], mappings [] [2014-01-06 08:41:02,204][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] getAdminDb: isMaster: { "serverUsed" : "localhost/127.0.0.1:27017" , "ismaster" : true , "maxBsonObjectSize" : 16777216 , "maxMessageSizeBytes" : 48000000 , "localTime" : { "$date" : "2014-01-06T15:41:02.202Z"} , "ok" : 1.0} [2014-01-06 08:41:02,204][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] MongoAdminUser: - authenticated: false [2014-01-06 08:41:02,204][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Found admin database [2014-01-06 08:41:02,205][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] About to execute: { "serverStatus" : 1 , "asserts" : 0 , "backgroundFlushing" : 0 , "connections" : 0 , "cursors" : 0 , "dur" : 0 , "extra_info" : 0 , "globalLock" : 0 , "indexCounters" : 0 , "locks" : 0 , "metrics" : 0 , "network" : 0 , "opcounters" : 0 , "opcountersRepl" : 0 , "recordStats" : 0 , "repl" : 0} [2014-01-06 08:41:02,207][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Command executed return : { "serverUsed" : "localhost/127.0.0.1:27017" , "host" : "coelacanth" , "version" : "2.4.8" , "process" : "mongod" , "pid" : 91702 , "uptime" : 7.0 , "uptimeMillis" : 6851 , "uptimeEstimate" : 5.0 , "localTime" : { "$date" : "2014-01-06T15:41:02.206Z"} , "ok" : 1.0} [2014-01-06 08:41:02,207][INFO ][org.elasticsearch.river.mongodb.MongoDBRiver] MongoDB version - 2.4.8 [2014-01-06 08:41:02,207][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] serverStatus: { "serverUsed" : "localhost/127.0.0.1:27017" , "host" : "coelacanth" , "version" : "2.4.8" , "process" : "mongod" , "pid" : 91702 , "uptime" : 7.0 , "uptimeMillis" : 6851 , "uptimeEstimate" : 5.0 , "localTime" : { "$date" : "2014-01-06T15:41:02.206Z"} , "ok" : 1.0} [2014-01-06 08:41:02,208][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] process: mongod [2014-01-06 08:41:02,208][TRACE][org.elasticsearch.river.mongodb.MongoDBRiver] Not mongos [2014-01-06 08:41:02,222][INFO ][org.elasticsearch.river.mongodb.Slurper] MongoDBRiver is beginning initial import of bulbDev.units [2014-01-06 08:41:02,233][INFO ][org.elasticsearch.river.mongodb.Slurper] Collection units - count: 18 [2014-01-06 08:41:02,254][INFO ][org.elasticsearch.river.mongodb.Slurper] Number documents indexed: 18 [2014-01-06 08:41:02,327][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_index] update_mapping unit [2014-01-06 08:41:02,355][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_river-stats] creating index, cause [auto(index api)], shards [1]/[0], mappings [] [2014-01-06 08:41:02,409][INFO ][cluster.metadata ] [Devil's Sooty Brother] [units_river-stats] update_mapping stats [2014-01-06 08:41:02,789][INFO ][cluster.metadata ] [Devil's Sooty Brother] [_river] update_mapping units_river

And searches work as expected.

Thanks for your help!

David Haimson

richardwilly98 / elasticsearch-river-mongodb