read operation to server failed on database local

[dblado]

I've been seeing the following exception in elasticsearch today:

[2013-09-12 22:36:49,823][ERROR][river.mongodb ] [M] [mongodb][vendors_river] Mongo gave an exception
com.mongodb.MongoException$Network: Read operation to server ip-10-181-140-155/10.181.140.155:27017 failed on database local
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:253)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:216)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:288)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:273)
at com.mongodb.DBCursor._check(DBCursor.java:368)
at com.mongodb.DBCursor._hasNext(DBCursor.java:459)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.elasticsearch.river.mongodb.MongoDBRiver$Slurper.run(MongoDBRiver.java:1211)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:146)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at org.bson.io.Bits.readFully(Bits.java:46)
at org.bson.io.Bits.readFully(Bits.java:33)
at org.bson.io.Bits.readFully(Bits.java:28)
at com.mongodb.Response.(Response.java:40)
at com.mongodb.DBPort.go(DBPort.java:142)
at com.mongodb.DBPort.call(DBPort.java:92)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:244)
... 8 more

I did add two indexes to my mongo collection last night. In the mongo I see the following query executing (the client is the elasticsearch river):

    {
        "opid" : 3150,
        "active" : true,
        "secs_running" : 40,
        "op" : "query",
        "ns" : "local.oplog.rs",
        "query" : {
            "$query" : {
                "$and" : [
                    {
                        "$or" : [
                            {
                                "ns" : "vendop.vendor"
                            },
                            {
                                "ns" : "vendop.$cmd"
                            }
                        ]
                    },
                    {
                        "ts" : {
                            "$gt" : Timestamp(1378589134, 45)
                        }
                    }
                ]
            },
            "$orderby" : {
                "$natural" : 1
            }
        },
        "client" : "10.159.61.227:38940",
        "desc" : "conn103",
        "threadId" : "0x7f31d9c25700",
        "connectionId" : 103,
        "locks" : {
            "^" : "r",
            "^local" : "R"
        },
        "waitingForLock" : false,
        "numYields" : 171,
        "lockStats" : {
            "timeLockedMicros" : {
                "r" : NumberLong(79863946),
                "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(40534881),
                "w" : NumberLong(0)
            }
        }
    }
]

}

one of these queries takes a long time to execute:

Thu Sep 12 22:37:21.277 [conn87] query local.oplog.rs query: { $query: { $and: [ { $or: [ { ns: "vendop.vendor" }, { ns: "vendop.$cmd" } ] }, { ts: { $gt: Timestamp 1378589134000|45 } } ] }, $orderby: { $natural: 1 } } cursorid:22909236201096610 ntoreturn:0 ntoskip:0 nscanned:18878069 keyUpdates:0 numYields: 3873 locks(micros) r:1835294560 nreturned:92 reslen:15638 932067ms

Thu Sep 12 22:37:21.277 [conn90] query local.oplog.rs query: { $query: { $and: [ { $or: [ { ns: "vendop.vendor" }, { ns: "vendop.$cmd" } ] }, { ts: { $gt: Timestamp 1378589134000|45 } } ] }, $orderby: { $natural: 1 } } cursorid:22909235441195695 ntoreturn:0 ntoskip:0 nscanned:18878069 keyUpdates:0 numYields: 3099 locks(micros) r:1480829880 nreturned:92 reslen:15638 751916ms

Thu Sep 12 22:37:21.277 [conn91] query local.oplog.rs query: { $query: { $and: [ { $or: [ { ns: "vendop.vendor" }, { ns: "vendop.$cmd" } ] }, { ts: { $gt: Timestamp 1378589134000|45 } } ] }, $orderby: { $natural: 1 } } cursorid:22909237130526342 ntoreturn:0 ntoskip:0 nscanned:18878069 keyUpdates:0 numYields: 2894 locks(micros) r:1362870376 nreturned:92 reslen:15638 691878ms

Thu Sep 12 22:37:21.278 [conn85] query local.oplog.rs query: { $query: { $and: [ { $or: [ { ns: "vendop.vendor" }, { ns: "vendop.$cmd" } ] }, { ts: { $gt: Timestamp 1378589134000|45 } } ] }, $orderby: { $natural: 1 } } cursorid:22909235755883542 ntoreturn:0 ntoskip:0 nscanned:18878069 keyUpdates:0 numYields: 4315 locks(micros) r:2072460163 nreturned:92 reslen:15638 1052126ms

I'm on es 0.90.3, river-mongodb 1.7.0, mongodb 2.4.5.

any ideas what is causing the queries from river-mongodb to mongo to take so long to run?

[dblado]

updated w/ more log info:

The org.elasticsearch.action.NoShardAvailableActionException is also new. Any help would be greatly appreciated.

[2013-09-13 04:06:41,811][INFO ][node ] [Spiral] version[0.90.3], pid[11057], build[5c38d60/2013-08-06T13:18:31Z]
[2013-09-13 04:06:41,812][INFO ][node ] [Spiral] initializing ...
[2013-09-13 04:06:41,873][INFO ][plugins ] [Spiral] loaded [mongodb-river, mapper-attachments, lang-javascript], sites [river-mongodb, head]
[2013-09-13 04:06:44,635][INFO ][node ] [Spiral] initialized
[2013-09-13 04:06:44,635][INFO ][node ] [Spiral] starting ...
[2013-09-13 04:06:44,738][INFO ][transport ] [Spiral] bound_address {inet[/0:0:0:0:0:0:0:0:9300]}, publish_address {inet[/10.159.61.227:9300]}
[2013-09-13 04:06:47,774][INFO ][cluster.service ] [Spiral] new_master [Spiral][1-o0xVXqTw-hIS9zNXLnZA][inet[/10.159.61.227:9300]], reason: zen-disco-join (elected_as_master)
[2013-09-13 04:06:47,810][INFO ][discovery ] [Spiral] elasticsearch/1-o0xVXqTw-hIS9zNXLnZA
[2013-09-13 04:06:47,838][INFO ][http ] [Spiral] bound_address {inet[/0:0:0:0:0:0:0:0:9200]}, publish_address {inet[/10.159.61.227:9200]}
[2013-09-13 04:06:47,839][INFO ][node ] [Spiral] started
[2013-09-13 04:06:47,861][DEBUG][action.get ] [Spiral] [_river][0]: failed to execute [[_river][vendors_river][_meta]: routing [null]]
org.elasticsearch.action.NoShardAvailableActionException: [_river][0] null
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction$AsyncSingleAction.start(TransportShardSingleOperationAction.java:123)
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:72)
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:47)
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:61)
at org.elasticsearch.client.node.NodeClient.execute(NodeClient.java:92)
at org.elasticsearch.client.support.AbstractClient.get(AbstractClient.java:179)
at org.elasticsearch.action.get.GetRequestBuilder.doExecute(GetRequestBuilder.java:112)
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:85)
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:59)
at org.elasticsearch.river.routing.RiversRouter$1.execute(RiversRouter.java:109)
at org.elasticsearch.river.cluster.RiverClusterService$1.run(RiverClusterService.java:103)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
[2013-09-13 04:06:48,773][INFO ][gateway ] [Spiral] recovered [2] indices into cluster_state
[2013-09-13 04:06:49,122][DEBUG][action.get ] [Spiral] [_river][0]: failed to execute [[_river][vendors_river][_meta]: routing [null]]
org.elasticsearch.action.NoShardAvailableActionException: [_river][0] null
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction$AsyncSingleAction.start(TransportShardSingleOperationAction.java:123)
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:72)
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:47)
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:61)
at org.elasticsearch.client.node.NodeClient.execute(NodeClient.java:92)
at org.elasticsearch.client.support.AbstractClient.get(AbstractClient.java:179)
at org.elasticsearch.action.get.GetRequestBuilder.doExecute(GetRequestBuilder.java:112)
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:85)
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:59)
at org.elasticsearch.river.routing.RiversRouter$1.execute(RiversRouter.java:109)
at org.elasticsearch.river.cluster.RiverClusterService$1.run(RiverClusterService.java:103)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
[2013-09-13 04:06:49,344][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] Prefix: [[Spiral] [mongodb][vendors_river] ] - name: [river.mongodb]
[2013-09-13 04:06:49,355][INFO ][river.mongodb ] mongoServersSettings: [{port=27017, host=db.prod.vendop.com}]
[2013-09-13 04:06:49,356][INFO ][river.mongodb ] Server: db.prod.vendop.com - 27017
[2013-09-13 04:06:49,359][TRACE][river.mongodb ] mongoOptionsSettings: {initial_timestamp={script_type=js, script=var date = new Date(); date.setSeconds(date.getSeconds() + 5); new java.lang.Long(date.getTime());}, secondary_read_preference=true}
[2013-09-13 04:06:49,730][TRACE][river.mongodb ] initialTimestamp script returned: 1379045214687
[2013-09-13 04:06:49,738][INFO ][river.mongodb ] [Spiral] [mongodb][vendors_river] Using mongodb server(s): host [db.prod.vendop.com], port [27017]
[2013-09-13 04:06:49,739][INFO ][river.mongodb ] [Spiral] [mongodb][vendors_river] MongoDB River Plugin version: [1.7.0]
[2013-09-13 04:06:49,739][INFO ][river.mongodb ] [Spiral] [mongodb][vendors_river] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [500], gridfs [false], filter [], db [vendop], collection [vendor], script [null], indexing to [vendors]/[vendop]
[2013-09-13 04:06:49,964][TRACE][river.mongodb ] [Spiral] [mongodb][vendors_river] serverStatus: { "serverUsed" : "ip-10-181-140-155/10.181.140.155:27017" , "host" : "ip-10-181-140-155" , "version" : "2.4.5" , "process" : "mongod" , "pid" : 1719 , "uptime" : 25144.0 , "uptimeMillis" : 25144689 , "uptimeEstimate" : 24948.0 , "localTime" : { "$date" : "2013-09-13T04:06:49.934Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 0 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 419 , "total_ms" : 366 , "average_ms" : 0.8735083532219571 , "last_ms" : 0 , "last_finished" : { "$date" : "2013-09-13T04:06:45.362Z"}} , "connections" : { "current" : 32 , "available" : 19968 , "totalCreated" : 476} , "cursors" : { "totalOpen" : 34 , "clientCursors_size" : 34 , "timedOut" : 388 , "totalNoTimeout" : 23} , "dur" : { "commits" : 88 , "journaledMB" : 0.0 , "writeToDataFilesMB" : 0.0 , "compression" : 0.0 , "commitsInWriteLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3026 , "prepLogBuffer" : 0 , "writeToJournal" : 0 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "heap_usage_bytes" : 64792968 , "page_faults" : 258863} , "globalLock" : { "totalTime" : 25144690000 , "lockTime" : 22065038 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 23 , "readers" : 23 , "writers" : 0}} , "indexCounters" : { "accesses" : 1050 , "hits" : 1050 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 1720996 , "W" : 22065038} , "timeAcquiringMicros" : { "R" : 2022298 , "W" : 859466476}} , "admin" : { "timeLockedMicros" : { } , "timeAcquiringMicros" : { }} , "local" : { "timeLockedMicros" : { "r" : 820853527560 , "w" : 66890} , "timeAcquiringMicros" : { "r" : 417564575283 , "w" : 894218}} , "vendop" : { "timeLockedMicros" : { "r" : 3367283 , "w" : 1696108} , "timeAcquiringMicros" : { "r" : 1756863 , "w" : 140851}} , "config" : { "timeLockedMicros" : { "r" : 23137 , "w" : 0} , "timeAcquiringMicros" : { "r" : 1159 , "w" : 0}}} , "network" : { "bytesIn" : 807799 , "bytesOut" : 15995589 , "numRequests" : 12997} , "opcounters" : { "insert" : 55 , "query" : 2600 , "update" : 11 , "delete" : 1 , "getmore" : 0 , "command" : 11593} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 337 , "pageFaultExceptionsThrown" : 324 , "config" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 1} , "vendop" : { "accessesNotInMemory" : 336 , "pageFaultExceptionsThrown" : 323}} , "repl" : { "setName" : "set1" , "ismaster" : true , "secondary" : false , "hosts" : [ "ip-10-181-140-155:27017"] , "primary" : "ip-10-181-140-155:27017" , "me" : "ip-10-181-140-155:27017"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 7313 , "virtual" : 33443 , "supported" : true , "mapped" : 16409 , "mappedWithJournal" : 32818} , "metrics" : { "document" : { "deleted" : 1 , "inserted" : 55 , "returned" : 42419 , "updated" : 11} , "getLastError" : { "wtime" : { "num" : 0 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 3 , "idhack" : 247 , "scanAndOrder" : 17} , "queryExecutor" : { "scanned" : 7532378605} , "record" : { "moves" : 3} , "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" : 68 , "totalMillis" : 11} , "insertBytes" : 13725} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 419}} , "ok" : 1.0}
[2013-09-13 04:06:49,964][TRACE][river.mongodb ] [Spiral] [mongodb][vendors_river] process: mongod
[2013-09-13 04:06:50,005][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] vendop.vendor last timestamp: { "$ts" : 1378589134 , "$inc" : 45}
[2013-09-13 04:06:50,009][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] Using filter: { "$and" : [ { "$or" : [ { "ns" : "vendop.vendor"} , { "ns" : "vendop.$cmd"}]} , { "ts" : { "$gt" : { "$ts" : 1378589134 , "$inc" : 45}}}]}

[2013-09-13 04:07:50,074][ERROR][river.mongodb ] [Spiral] [mongodb][vendors_river] Mongo gave an exception
com.mongodb.MongoException$Network: Read operation to server ip-10-181-140-155/10.181.140.155:27017 failed on database local
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:253)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:216)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:288)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:273)
at com.mongodb.DBCursor._check(DBCursor.java:368)
at com.mongodb.DBCursor._hasNext(DBCursor.java:459)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.elasticsearch.river.mongodb.MongoDBRiver$Slurper.run(MongoDBRiver.java:1211)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:146)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at org.bson.io.Bits.readFully(Bits.java:46)
at org.bson.io.Bits.readFully(Bits.java:33)
at org.bson.io.Bits.readFully(Bits.java:28)
at com.mongodb.Response.(Response.java:40)
at com.mongodb.DBPort.go(DBPort.java:142)
at com.mongodb.DBPort.call(DBPort.java:92)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:244)
... 8 more
[2013-09-13 04:07:50,077][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] vendop.vendor last timestamp: { "$ts" : 1378589134 , "$inc" : 45}
[2013-09-13 04:07:50,078][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] Using filter: { "$and" : [ { "$or" : [ { "ns" : "vendop.vendor"} , { "ns" : "vendop.$cmd"}]} , { "ts" : { "$gt" : { "$ts" : 1378589134 , "$inc" : 45}}}]}
[2013-09-13 04:08:50,138][ERROR][river.mongodb ] [Spiral] [mongodb][vendors_river] Mongo gave an exception
com.mongodb.MongoException$Network: Read operation to server ip-10-181-140-155/10.181.140.155:27017 failed on database local
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:253)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:216)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:288)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:273)
at com.mongodb.DBCursor._check(DBCursor.java:368)
at com.mongodb.DBCursor._hasNext(DBCursor.java:459)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.elasticsearch.river.mongodb.MongoDBRiver$Slurper.run(MongoDBRiver.java:1211)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:146)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at org.bson.io.Bits.readFully(Bits.java:46)
at org.bson.io.Bits.readFully(Bits.java:33)
at org.bson.io.Bits.readFully(Bits.java:28)
at com.mongodb.Response.(Response.java:40)
at com.mongodb.DBPort.go(DBPort.java:142)
at com.mongodb.DBPort.call(DBPort.java:92)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:244)
... 8 more
[2013-09-13 04:08:50,141][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] vendop.vendor last timestamp: { "$ts" : 1378589134 , "$inc" : 45}
[2013-09-13 04:08:50,142][DEBUG][river.mongodb ] [Spiral] [mongodb][vendors_river] Using filter: { "$and" : [ { "$or" : [ { "ns" : "vendop.vendor"} , { "ns" : "vendop.$cmd"}]} , { "ts" : { "$gt" : { "$ts" : 1378589134 , "$inc" : 45}}}]}

[richardwilly98]

How big is "oplog.rs" collection?
The river is using a tailable cursor to query this capped collection so that should be fast.
Regarding the second exception "org.elasticsearch.action.NoShardAvailableActionException" it is a new known issue with ES 0.90.3. It does not seem to affect the river but I am currently looking at it.

[dblado]

the oplog.rs collection is 9553 (I believe):

set1:PRIMARY> db.printReplicationInfo()
configured oplog size: 9553.9705078125MB
log length start to end: 2219103secs (616.42hrs)
oplog first event time: Sun Aug 18 2013 21:05:59 GMT+0000 (UTC)
oplog last event time: Fri Sep 13 2013 13:31:02 GMT+0000 (UTC)
now: Fri Sep 13 2013 15:58:46 GMT+0000 (UTC)
set1:PRIMARY> db.getReplicationInfo()
{
"logSizeMB" : 9553.9705078125,
"usedMB" : 8992.25,
"timeDiff" : 2219103,
"timeDiffHours" : 616.42,
"tFirst" : "Sun Aug 18 2013 21:05:59 GMT+0000 (UTC)",
"tLast" : "Fri Sep 13 2013 13:31:02 GMT+0000 (UTC)",
"now" : "Fri Sep 13 2013 15:58:58 GMT+0000 (UTC)"
}

[richardwilly98]

@dblado I was actually asking the number of rows in "oplog.rs" (sorry for the confusion).

The way the river monitors this collection is the recommended way by Mongo [1] to access mapped collection using a tailable cursor.

I have the feeling something is not correctly setup in your MongoDB instance.

[1] - http://docs.mongodb.org/manual/tutorial/create-tailable-cursor/

[dblado]

no worries -- db.oplog.rs.count() shows 18878152 records

On Fri, Sep 13, 2013 at 9:16 AM, Richard Louapre
notifications@github.comwrote:

@dblado https://github.com/dblado I was actually asking the number of
rows in "oplog.rs" (sorry for the confusion).

The way the river monitors this collection is the recommended way by Mongo
[1] to access mapped collection using a tailable cursor.

I have the feeling something is not correctly setup in your MongoDB
instance.

[1] - http://docs.mongodb.org/manual/tutorial/create-tailable-cursor/

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/123#issuecomment-24405936
.

[richardwilly98]

Hi,

There are actually hardcoded values for "connect timeout" and "socket timeout" in the current implementation... That seems to be the issue has it takes more than 15 seconds in your scenario.

    // TODO: MongoClientOptions should be configurable
    private Mongo getMongoClient() {
        if (mongo == null) {
            Builder builder = MongoClientOptions.builder()
                    .autoConnectRetry(true).connectTimeout(15000)
                    .socketKeepAlive(true).socketTimeout(60000);
            if (definition.isMongoUseSSL()) {
                builder.socketFactory(getSSLSocketFactory());
            }

            MongoClientOptions mco = builder.build();
            mongo = new MongoClient(definition.getMongoServers(), mco);
        }
        return mongo;
    }

I will make a change to be able to specify these parameters in the river settings.

[dblado]

Yea but I don't the indexing through the river to be taking so darn long --
I want as near real time as possible. I have the db and es on 2 m1.large
instances in EC2 -- could my problem be undersized hardware or nodes?

On Fri, Sep 13, 2013 at 9:37 AM, Richard Louapre
notifications@github.comwrote:

Hi,

There are actually hardcoded values for "connect timeout" and "socket
timeout" in the current implementation... That seems to be the issue has it
takes more than 15 seconds in your scenario.

// TODO: MongoClientOptions should be configurable
private Mongo getMongoClient() {
    if (mongo == null) {
        Builder builder = MongoClientOptions.builder()
                .autoConnectRetry(true).connectTimeout(15000)
                .socketKeepAlive(true).socketTimeout(60000);
        if (definition.isMongoUseSSL()) {
            builder.socketFactory(getSSLSocketFactory());
        }

        MongoClientOptions mco = builder.build();
        mongo = new MongoClient(definition.getMongoServers(), mco);
    }
    return mongo;
}

I will make a change to be able to specify these parameters in the river
settings.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/123#issuecomment-24407363
.

[dblado]

the queries that the river sends to mongo are taking 20+ minutes to execute. the load on both m1.large instances are near 0 since i'm the only one using it at the moment. there might be a few other hits to the db and es from the app but not much

[richardwilly98]

Can you do an .explain() on the query to see if it can be optimized or indexes can be created?
I will have a new SNAPSHOT ready for testing soon (if you are interested).

[dblado]

not sure how to do the explain...I thought I could do:

set1:PRIMARY> db.oplog.rs.find({ $query: { $and: [ { $or: [ { ns: "vendop.vendor" }, { ns: "vendop.$cmd" } ] }, { ts: { $gt: Timestamp 1378589134000|45 } } ] }, $orderby: { $natural: 1 } }).explain()
Fri Sep 13 17:24:15.723 JavaScript execution failed: SyntaxError: Unexpected number

I just copied one of the offending queries from the mongo logfile

[dblado]

ya, send me a jar file w/ the timeout hardcode increased (or customizable) and I'll give it a try -- maybe once the river receives the response to this specific query my problem will go away. Although I did set an initial timestamp on the river to force to ignore old oplog entries

[richardwilly98]

Here is the snapshot [1]. Please give it a try.

No need to change the river settings.

Just stop ES replace the jar files and restart.

[1] - https://dl.dropboxusercontent.com/u/64847502/elasticsearch-river-mongodb-1.7.1-SNAPSHOT.zip

[dblado]

still seeing the read timed out exception:

[2013-09-13 17:31:45,243][INFO ][node ] [Jimmy Woo] version[0.90.3], pid[13379], build[5c38d60/2013-08-06T13:18:31Z]
[2013-09-13 17:31:45,244][INFO ][node ] [Jimmy Woo] initializing ...
[2013-09-13 17:31:45,306][INFO ][plugins ] [Jimmy Woo] loaded [mongodb-river, mapper-attachments, lang-javascript], sites [river-mongodb, head]
[2013-09-13 17:31:48,056][INFO ][node ] [Jimmy Woo] initialized
[2013-09-13 17:31:48,056][INFO ][node ] [Jimmy Woo] starting ...
[2013-09-13 17:31:48,157][INFO ][transport ] [Jimmy Woo] bound_address {inet[/0:0:0:0:0:0:0:0:9300]}, publish_address {inet[/10.159.61.227:9300]}
[2013-09-13 17:31:51,193][INFO ][cluster.service ] [Jimmy Woo] new_master [Jimmy Woo][rLYcLpO8QtyDJ1JaGrRvIg][inet[/10.159.61.227:9300]], reason: zen-disco-join (elected_as_master)
[2013-09-13 17:31:51,229][INFO ][discovery ] [Jimmy Woo] elasticsearch/rLYcLpO8QtyDJ1JaGrRvIg
[2013-09-13 17:31:51,246][INFO ][http ] [Jimmy Woo] bound_address {inet[/0:0:0:0:0:0:0:0:9200]}, publish_address {inet[/10.159.61.227:9200]}
[2013-09-13 17:31:51,246][INFO ][node ] [Jimmy Woo] started
[2013-09-13 17:31:51,281][DEBUG][action.get ] [Jimmy Woo] [_river][0]: failed to execute [[_river][vendors_river][_meta]: routing [null]]
org.elasticsearch.action.NoShardAvailableActionException: [_river][0] null
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction$AsyncSingleAction.start(TransportShardSingleOperationAction.java:123)
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:72)
at org.elasticsearch.action.support.single.shard.TransportShardSingleOperationAction.doExecute(TransportShardSingleOperationAction.java:47)
at org.elasticsearch.action.support.TransportAction.execute(TransportAction.java:61)
at org.elasticsearch.client.node.NodeClient.execute(NodeClient.java:92)
at org.elasticsearch.client.support.AbstractClient.get(AbstractClient.java:179)
at org.elasticsearch.action.get.GetRequestBuilder.doExecute(GetRequestBuilder.java:112)
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:85)
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:59)
at org.elasticsearch.river.routing.RiversRouter$1.execute(RiversRouter.java:109)
at org.elasticsearch.river.cluster.RiverClusterService$1.run(RiverClusterService.java:103)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:679)
[2013-09-13 17:31:52,232][INFO ][gateway ] [Jimmy Woo] recovered [2] indices into cluster_state
[2013-09-13 17:31:52,396][DEBUG][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] Prefix: [[Jimmy Woo] [mongodb][vendors_river] ] - name: [river.mongodb]
[2013-09-13 17:31:52,406][INFO ][river.mongodb ] mongoServersSettings: [{port=27017, host=db.prod.vendop.com}]
[2013-09-13 17:31:52,406][INFO ][river.mongodb ] Server: db.prod.vendop.com - 27017
[2013-09-13 17:31:52,568][TRACE][river.mongodb ] mongoOptionsSettings: {initial_timestamp={script_type=js, script=var date = new Date(); date.setSeconds(date.getSeconds() + 5); new java.lang.Long(date.getTime());}, secondary_read_preference=true}
[2013-09-13 17:31:52,827][TRACE][river.mongodb ] initialTimestamp script returned: 1379093517797
[2013-09-13 17:31:52,835][INFO ][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] Using mongodb server(s): host [db.prod.vendop.com], port [27017]
[2013-09-13 17:31:52,836][INFO ][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] MongoDB River Plugin version: [1.7.0]
[2013-09-13 17:31:52,836][INFO ][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] starting mongodb stream. options: secondaryreadpreference [true], drop_collection [false], include_collection [], throttlesize [500], gridfs [false], filter [], db [vendop], collection [vendor], script [null], indexing to [vendors]/[vendop]
[2013-09-13 17:31:53,286][TRACE][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] serverStatus: { "serverUsed" : "ip-10-181-140-155/10.181.140.155:27017" , "host" : "ip-10-181-140-155" , "version" : "2.4.5" , "process" : "mongod" , "pid" : 4808 , "uptime" : 41183.0 , "uptimeMillis" : 41182854 , "uptimeEstimate" : 40862.0 , "localTime" : { "$date" : "2013-09-13T17:31:53.170Z"} , "asserts" : { "regular" : 0 , "warning" : 0 , "msg" : 0 , "user" : 0 , "rollovers" : 0} , "backgroundFlushing" : { "flushes" : 686 , "total_ms" : 136 , "average_ms" : 0.19825072886297376 , "last_ms" : 0 , "last_finished" : { "$date" : "2013-09-13T17:31:30.401Z"}} , "connections" : { "current" : 31 , "available" : 19969 , "totalCreated" : 699} , "cursors" : { "totalOpen" : 34 , "clientCursors_size" : 34 , "timedOut" : 652 , "totalNoTimeout" : 20} , "dur" : { "commits" : 88 , "journaledMB" : 0.0 , "writeToDataFilesMB" : 0.0 , "compression" : 0.0 , "commitsInWriteLock" : 0 , "earlyCommits" : 0 , "timeMs" : { "dt" : 3033 , "prepLogBuffer" : 0 , "writeToJournal" : 0 , "writeToDataFiles" : 0 , "remapPrivateView" : 0}} , "extra_info" : { "note" : "fields vary by platform" , "heap_usage_bytes" : 64683304 , "page_faults" : 372578} , "globalLock" : { "totalTime" : 41182884000 , "lockTime" : 22903163 , "currentQueue" : { "total" : 0 , "readers" : 0 , "writers" : 0} , "activeClients" : { "total" : 20 , "readers" : 20 , "writers" : 0}} , "indexCounters" : { "accesses" : 318 , "hits" : 318 , "misses" : 0 , "resets" : 0 , "missRatio" : 0.0} , "locks" : { "." : { "timeLockedMicros" : { "R" : 2835632 , "W" : 22903163} , "timeAcquiringMicros" : { "R" : 3015339 , "W" : 1469808177}} , "admin" : { "timeLockedMicros" : { } , "timeAcquiringMicros" : { }} , "local" : { "timeLockedMicros" : { "r" : 1429902579128 , "w" : 58855} , "timeAcquiringMicros" : { "r" : 727932420060 , "w" : 227207}} , "vendop" : { "timeLockedMicros" : { "r" : 2435005 , "w" : 1234970} , "timeAcquiringMicros" : { "r" : 828842 , "w" : 55977}} , "test" : { "timeLockedMicros" : { "r" : 18719 , "w" : 0} , "timeAcquiringMicros" : { "r" : 90 , "w" : 0}}} , "network" : { "bytesIn" : 1105334 , "bytesOut" : 10207728 , "numRequests" : 18142} , "opcounters" : { "insert" : 9 , "query" : 2973 , "update" : 5 , "delete" : 1 , "getmore" : 0 , "command" : 16927} , "opcountersRepl" : { "insert" : 0 , "query" : 0 , "update" : 0 , "delete" : 0 , "getmore" : 0 , "command" : 0} , "recordStats" : { "accessesNotInMemory" : 102 , "pageFaultExceptionsThrown" : 93 , "local" : { "accessesNotInMemory" : 1 , "pageFaultExceptionsThrown" : 1} , "test" : { "accessesNotInMemory" : 0 , "pageFaultExceptionsThrown" : 0} , "vendop" : { "accessesNotInMemory" : 101 , "pageFaultExceptionsThrown" : 92}} , "repl" : { "setName" : "set1" , "ismaster" : true , "secondary" : false , "hosts" : [ "ip-10-181-140-155:27017"] , "primary" : "ip-10-181-140-155:27017" , "me" : "ip-10-181-140-155:27017"} , "writeBacksQueued" : false , "mem" : { "bits" : 64 , "resident" : 7283 , "virtual" : 33602 , "supported" : true , "mapped" : 16489 , "mappedWithJournal" : 32978} , "metrics" : { "document" : { "deleted" : 1 , "inserted" : 9 , "returned" : 72010 , "updated" : 5} , "getLastError" : { "wtime" : { "num" : 0 , "totalMillis" : 0} , "wtimeouts" : 0} , "operation" : { "fastmod" : 1 , "idhack" : 82 , "scanAndOrder" : 6} , "queryExecutor" : { "scanned" : 12572869515} , "record" : { "moves" : 3} , "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" : 14 , "totalMillis" : 5} , "insertBytes" : 4388} , "preload" : { "docs" : { "num" : 0 , "totalMillis" : 0} , "indexes" : { "num" : 0 , "totalMillis" : 0}}} , "ttl" : { "deletedDocuments" : 0 , "passes" : 686}} , "ok" : 1.0}
[2013-09-13 17:31:53,286][TRACE][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] process: mongod
[2013-09-13 17:31:53,346][DEBUG][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] vendop.vendor last timestamp: { "$ts" : 1378589134 , "$inc" : 45}
[2013-09-13 17:31:53,350][DEBUG][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] Using filter: { "$and" : [ { "$or" : [ { "ns" : "vendop.vendor"} , { "ns" : "vendop.$cmd"}]} , { "ts" : { "$gt" : { "$ts" : 1378589134 , "$inc" : 45}}}]}

[2013-09-13 17:32:53,383][ERROR][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] Mongo gave an exception
com.mongodb.MongoException$Network: Read operation to server ip-10-181-140-155/10.181.140.155:27017 failed on database local
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:253)
at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:216)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:288)
at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:273)
at com.mongodb.DBCursor._check(DBCursor.java:368)
at com.mongodb.DBCursor._hasNext(DBCursor.java:459)
at com.mongodb.DBCursor.hasNext(DBCursor.java:484)
at org.elasticsearch.river.mongodb.MongoDBRiver$Slurper.run(MongoDBRiver.java:1211)
at java.lang.Thread.run(Thread.java:679)
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:146)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:275)
at java.io.BufferedInputStream.read(BufferedInputStream.java:334)
at org.bson.io.Bits.readFully(Bits.java:46)
at org.bson.io.Bits.readFully(Bits.java:33)
at org.bson.io.Bits.readFully(Bits.java:28)
at com.mongodb.Response.(Response.java:40)
at com.mongodb.DBPort.go(DBPort.java:142)
at com.mongodb.DBPort.call(DBPort.java:92)
at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:244)
... 8 more
[2013-09-13 17:32:53,386][DEBUG][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] vendop.vendor last timestamp: { "$ts" : 1378589134 , "$inc" : 45}
[2013-09-13 17:32:53,387][DEBUG][river.mongodb ] [Jimmy Woo] [mongodb][vendors_river] Using filter: { "$and" : [ { "$or" : [ { "ns" : "vendop.vendor"} , { "ns" : "vendop.$cmd"}]} , { "ts" : { "$gt" : { "$ts" : 1378589134 , "$inc" : 45}}}]}

[dblado]

this explain seems to be doing something:
set1:PRIMARY> db.oplog.rs.find({ "$and" : [ { "$or" : [ { "ns" : "vendop.vendor"} , { "ns" : "vendop.$cmd"}]} , { "ts" : { "$gt" : { "$ts" : 1378589134 , "$inc" : 45}}}]}).explain()

it's been running a couple minutes already but I guess that's normal because the explain() still runs the query normally just outputs additional data??

[richardwilly98]

I don't believe you are have correctly the SNAPHOT version. The log file should show:
MongoDB River Plugin version: [1.7.1-SNAPSHOT] instead of MongoDB River Plugin version: [1.7.0]

Did you replace elasticsearch-river-mongodb-1.7.0.jar by elasticsearch-river-mongodb-1.7.1-SNAPSHOT.jar in $ES_HOME/plugins/river-mongodb?